Skip to content

Commit 00d45d4

Browse files
pekkaklarckpekkaklarck
committed
Pause timeouts when library keyword uses BuiltIn.run_keyword
This prevents timeouts occurring when Robot is writing output files and thus avoids output files getting corrupted. Fixes #5417. Thanks to the refactoring in the previous commit, implementation is relatively simple. Also make sure delayed messages (#2839) are logged in correct order when `BuiltIn.run_keyword` is used. Fixes #5423.
1 parent 66d5300 commit 00d45d4

File tree

13 files changed

+116
-27
lines changed

13 files changed

+116
-27
lines changed

‎atest/robot/standard_libraries/builtin/used_in_custom_libs_and_listeners.robot

Lines changed: 24 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,7 @@
11
*** Settings ***
2-
Documentation These tests mainly verify that using BuiltIn externally does not cause importing problems as in
3-
... https://github.com/robotframework/robotframework/issues/654.
4-
... There are separate tests for creating and registering Run Keyword variants.
5-
Suite Setup Run Tests --listener ${CURDIR}/listener_using_builtin.py standard_libraries/builtin/used_in_custom_libs_and_listeners.robot
2+
Suite Setup Run Tests
3+
... --listener ${CURDIR}/listener_using_builtin.py
4+
... standard_libraries/builtin/used_in_custom_libs_and_listeners.robot
65
Resource atest_resource.robot
76

87
*** Test Cases ***
@@ -25,21 +24,34 @@ Use BuiltIn keywords with timeouts
2524
Check Log Message ${tc[0, 0]} Log level changed from NONE to DEBUG. DEBUG
2625
Check Log Message ${tc[0, 1]} Hello, debug world! DEBUG
2726
Length should be ${tc[0].messages} 2
28-
Check Log Message ${tc[3, 0, 0]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
29-
Check Log Message ${tc[3, 0, 1]} 42
27+
Check Log Message ${tc[3, 0]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
3028
Check Log Message ${tc[3, 1, 0]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
31-
Check Log Message ${tc[3, 1, 1]} \xff
32-
# This message is in wrong place due to it being delayed and child keywords being logged first.
33-
# It should be in position [3, 0], not [3, 2].
34-
Check Log Message ${tc[3, 2]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
29+
Check Log Message ${tc[3, 1, 1]} 42
30+
Check Log Message ${tc[3, 2, 0]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
31+
Check Log Message ${tc[3, 2, 1]} \xff
3532

3633
User keyword used via 'Run Keyword'
3734
${tc} = Check Test Case ${TESTNAME}
38-
Check Log Message ${tc[0, 0, 0, 0]} This is x-911-zzz
35+
Check Log Message ${tc[0, 0]} Before
36+
Check Log Message ${tc[0, 1, 0, 0]} This is x-911-zzz
37+
Check Log Message ${tc[0, 2]} After
3938

4039
User keyword used via 'Run Keyword' with timeout and trace level
4140
${tc} = Check Test Case ${TESTNAME}
42-
Check Log Message ${tc[0, 1, 0, 1]} This is x-911-zzz
41+
Check Log Message ${tc[0, 0]} Arguments: [ \ ] level=TRACE
42+
Check Log Message ${tc[0, 1]} Test timeout 1 day active. * seconds left. level=DEBUG pattern=True
43+
Check Log Message ${tc[0, 2]} Before
44+
Check Log Message ${tc[0, 3, 0]} Arguments: [ \${x}='This is x' | \${y}=911 | \${z}='zzz' ] level=TRACE
45+
Check Log Message ${tc[0, 3, 1, 0]} Arguments: [ 'This is x-911-zzz' ] level=TRACE
46+
Check Log Message ${tc[0, 3, 1, 1]} Keyword timeout 1 hour active. * seconds left. level=DEBUG pattern=True
47+
Check Log Message ${tc[0, 3, 1, 2]} This is x-911-zzz
48+
Check Log Message ${tc[0, 3, 1, 3]} Return: None level=TRACE
49+
Check Log Message ${tc[0, 3, 2]} Return: None level=TRACE
50+
Check Log Message ${tc[0, 4]} After
51+
Check Log Message ${tc[0, 5]} Return: None level=TRACE
52+
53+
Timeout when running keyword that logs huge message
54+
Check Test Case ${TESTNAME}
4355

4456
Timeout in parent keyword after running keyword
4557
Check Test Case ${TESTNAME}

‎atest/testdata/standard_libraries/builtin/UseBuiltIn.py

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,10 @@
11
import time
22

3+
from robot.api import logger
34
from robot.libraries.BuiltIn import BuiltIn
45

6+
MSG = "A rather long message that is slow to write on the disk. " * 10000
7+
58

69
def log_messages_and_set_log_level():
710
b = BuiltIn()
@@ -26,7 +29,18 @@ def use_run_keyword_with_non_string_values():
2629

2730

2831
def user_keyword_via_run_keyword():
32+
logger.info('Before')
2933
BuiltIn().run_keyword("UseBuiltInResource.Keyword", "This is x", 911)
34+
logger.info('After')
35+
36+
37+
def run_keyword_that_logs_huge_message_until_timeout():
38+
while True:
39+
BuiltIn().run_keyword("Log Huge Message")
40+
41+
42+
def log_huge_message():
43+
logger.info(MSG)
3044

3145

3246
def timeout_in_parent_keyword_after_running_keyword():

‎atest/testdata/standard_libraries/builtin/UseBuiltInResource.robot

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
*** Keywords ***
22
Keyword
33
[Arguments] ${x} ${y} ${z}=zzz
4+
[Timeout] 1 hour
45
Log ${x}-${y}-${z}

‎atest/testdata/standard_libraries/builtin/used_in_custom_libs_and_listeners.robot

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,11 @@ User keyword used via 'Run Keyword' with timeout and trace level
3333
[Timeout] 1 day
3434
User Keyword via Run Keyword
3535

36+
Timeout when running keyword that logs huge message
37+
[Documentation] FAIL Test timeout 100 milliseconds exceeded.
38+
[Timeout] 0.1 s
39+
Run keyword that logs huge message until timeout
40+
3641
Timeout in parent keyword after running keyword
3742
[Documentation] FAIL Test timeout 100 milliseconds exceeded.
3843
[Timeout] 0.1 s

‎src/robot/libraries/BuiltIn.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2166,7 +2166,8 @@ def run_keyword(self, name, *args):
21662166
else:
21672167
result = ctx.suite.teardown
21682168
kw = Keyword(name, args=args, parent=data, lineno=lineno)
2169-
return kw.run(result, ctx)
2169+
with ctx.paused_timeouts:
2170+
return kw.run(result, ctx)
21702171

21712172
def _accepts_embedded_arguments(self, name, ctx):
21722173
# KeywordRunner.run has similar logic that's used with setups/teardowns.

‎src/robot/output/output.py

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,10 @@ def register_error_listener(self, listener):
5555
def delayed_logging(self):
5656
return self.output_file.delayed_logging
5757

58+
@property
59+
def delayed_logging_paused(self):
60+
return self.output_file.delayed_logging_paused
61+
5862
def close(self, result):
5963
self.output_file.statistics(result.statistics)
6064
self.output_file.close()

‎src/robot/output/outputfile.py

Lines changed: 16 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -63,9 +63,22 @@ def delayed_logging(self):
6363
try:
6464
yield
6565
finally:
66-
self._delayed_messages, messages = previous, self._delayed_messages
67-
for msg in messages:
68-
self.log_message(msg, no_delay=True)
66+
self._release_delayed_messages()
67+
self._delayed_messages = previous
68+
69+
@property
70+
@contextmanager
71+
def delayed_logging_paused(self):
72+
self._release_delayed_messages()
73+
self._delayed_messages = None
74+
try:
75+
yield
76+
finally:
77+
self._delayed_messages = []
78+
79+
def _release_delayed_messages(self):
80+
for msg in self._delayed_messages:
81+
self.log_message(msg, no_delay=True)
6982

7083
def start_suite(self, data, result):
7184
self.logger.start_suite(result)

‎src/robot/running/context.py

Lines changed: 30 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -102,7 +102,8 @@ class _ExecutionContext:
102102
def __init__(self, suite, namespace, output, dry_run=False, asynchronous=None):
103103
self.suite = suite
104104
self.test = None
105-
self.timeouts = set()
105+
self.timeouts = []
106+
self.active_timeouts = []
106107
self.namespace = namespace
107108
self.output = output
108109
self.dry_run = dry_run
@@ -166,13 +167,39 @@ def warn_on_invalid_private_call(self, handler):
166167
)
167168

168169
@contextmanager
169-
def timeout(self, timeout):
170+
def keyword_timeout(self, timeout):
170171
self._add_timeout(timeout)
171172
try:
172173
yield
173174
finally:
174175
self._remove_timeout(timeout)
175176

177+
@contextmanager
178+
def timeout(self, timeout):
179+
runner = timeout.get_runner()
180+
self.active_timeouts.append(runner)
181+
with self.output.delayed_logging:
182+
self.output.debug(timeout.get_message)
183+
try:
184+
yield runner
185+
finally:
186+
self.active_timeouts.pop()
187+
188+
@property
189+
@contextmanager
190+
def paused_timeouts(self):
191+
if not self.active_timeouts:
192+
yield
193+
return
194+
for runner in self.active_timeouts:
195+
runner.pause()
196+
with self.output.delayed_logging_paused:
197+
try:
198+
yield
199+
finally:
200+
for runner in self.active_timeouts:
201+
runner.resume()
202+
176203
@property
177204
def in_teardown(self):
178205
return bool(
@@ -245,7 +272,7 @@ def start_test(self, data, result):
245272
def _add_timeout(self, timeout):
246273
if timeout:
247274
timeout.start()
248-
self.timeouts.add(timeout)
275+
self.timeouts.append(timeout)
249276

250277
def _remove_timeout(self, timeout):
251278
if timeout in self.timeouts:

‎src/robot/running/librarykeywordrunner.py

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -55,6 +55,7 @@ def run(self, data: KeywordData, result: KeywordResult, context, run=True):
5555
return_value = self._run(data, kw, context)
5656
assigner.assign(return_value)
5757
return return_value
58+
return None
5859

5960
def _config_result(
6061
self,
@@ -115,18 +116,17 @@ def _get_timeout(self, context):
115116
def _execute(self, method, positional, named, context):
116117
timeout = self._get_timeout(context)
117118
if timeout:
118-
method = self._wrap_with_timeout(method, timeout, context.output)
119+
method = self._wrap_with_timeout(method, timeout, context)
119120
with self._monitor(context):
120121
result = method(*positional, **dict(named))
121122
if context.asynchronous.is_loop_required(result):
122123
return context.asynchronous.run_until_complete(result)
123124
return result
124125

125-
def _wrap_with_timeout(self, method, timeout, output):
126+
def _wrap_with_timeout(self, method, timeout, context):
126127
def wrapper(*args, **kwargs):
127-
with output.delayed_logging:
128-
output.debug(timeout.get_message)
129-
return timeout.run(method, args=args, kwargs=kwargs)
128+
with context.timeout(timeout) as runner:
129+
return runner.run(method, args=args, kwargs=kwargs)
130130

131131
return wrapper
132132

‎src/robot/running/timeouts/posix.py

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,9 @@ def _start_timer(self):
4646
type(self)._started += 1
4747

4848
def _raise_timeout(self, signum, frame):
49-
raise self.timeout_error
49+
self.exceeded = True
50+
if not self.paused:
51+
raise self.timeout_error
5052

5153
def _stop_timer(self):
5254
type(self)._started -= 1

‎src/robot/running/timeouts/runner.py

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ def __init__(
3232
self.timeout_error = timeout_error
3333
self.data_error = data_error
3434
self.exceeded = False
35+
self.paused = False
3536

3637
@classmethod
3738
def for_platform(
@@ -74,3 +75,11 @@ def run(
7475

7576
def _run(self, runnable: "Callable[[], object]") -> object:
7677
raise NotImplementedError
78+
79+
def pause(self):
80+
self.paused = True
81+
82+
def resume(self):
83+
self.paused = False
84+
if self.exceeded:
85+
raise self.timeout_error

‎src/robot/running/timeouts/windows.py

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,8 @@ def _run(self, runnable):
5151

5252
def _timeout_exceeded(self):
5353
self.exceeded = True
54-
self._raise_timeout()
54+
if not self.paused:
55+
self._raise_timeout()
5556

5657
def _raise_timeout(self):
5758
# See the following for the original recipe and API docs.

‎src/robot/running/userkeywordrunner.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -105,7 +105,7 @@ def _run(
105105
result.timeout = str(timeout) if timeout else None
106106
else:
107107
timeout = None
108-
with context.timeout(timeout):
108+
with context.keyword_timeout(timeout):
109109
exception, return_value = self._execute(kw, result, context)
110110
if exception and not exception.can_continue(context):
111111
if context.in_teardown and exception.keyword_timeout:

0 commit comments

Comments
 (0)