diff --git a/README.md b/README.md index d3b15d4..dc92c3e 100644 --- a/README.md +++ b/README.md @@ -1,5 +1,5 @@ -# robotframeworkNL - the oneliner -robotframeworkNL is a proving ground to boost Robot framework closer to Natural Language. +# RobotNL - the oneliner +RobotNL is a proving ground to boost Robot framework closer to Natural Language. ## Introduction This project is an extension to [Robot framework](https://robotframework.org/) and although [Robot framework](https://robotframework.org/) made a very good step towards the goals of [keyword-driven testing ](https://en.wikipedia.org/wiki/Keyword-driven_testing) to make it readable for all stakeholders, there is still quite a lot of syntax involved that keeps test cases from really staying concise and to-the-point. In this project we will be introducing concepts to lift [Robot framework](https://robotframework.org/) to an even higher level. @@ -55,17 +55,20 @@ Using *Check that* keywords offers a large reduction in the need for variables i ### Time constraints -*Check that* offers support for executing checks that may take some time to complete. When using the optional `within` argument, followed by a time duration, *Check that* will apply *smart polling* to re-evaluate the expression and the keywords during the given period. Specifying the time limit is done using the standard [Robot Framework time format](https://robotframework.org/robotframework/latest/RobotFrameworkUserGuide.html#toc-entry-176). It is advised to use a realistic time duration. This sets the correct expectation for the reader and helps robotnl optimise its polling algorithm. +*Check that* offers support for executing checks that may take some time to complete. When using the optional `within` argument, followed by a time duration, *Check that* will apply *smart polling* to re-evaluate the expression and the keywords during the given period. Specifying the time limit is done using the standard [Robot Framework time format](https://robotframework.org/robotframework/latest/RobotFrameworkUserGuide.html#toc-entry-176). It is advised to use a realistic time duration. This sets the correct expectation for the reader and helps RobotNL optimise its polling algorithm. |**Example using time constaints**|||||| |---|---|---|---|---|---| | Request elevator at floor | 3 ||||| | Check that | elevator doors are closed | within | 20 seconds || | Check that | current elevator floor | equals | 3 | within | 1 minute | +| Check that | elevator doors are opened | within | same timespan || + +The last line in the example uses the special argument `same timespan` to indicate that this check is linked to the same time constraint as the previous check. So, once the doors are closed, the elevator should not only reach the requested floor within 1 minute, but also the doors should be opened within that same 1-minute timespan. To use `within same timespan` you must have executed a check with a time constraint before. This is not necessarily the directly preceding line. The most recent time constraint set within scope is used as starting point. For test suites, that is the current test suite, for keywords that is the current keyword. ### Hybrid manual testing -To manually interact with your automated test run during testing or test case development, robotnl offers the *Check manual* and *Check interactive* keywords. These keywords can be included at any point in the test case to suspend the test run at the current position for user input. +To manually interact with your automated test run during testing or test case development, RobotNL offers the *Check manual* and *Check interactive* keywords. These keywords can be included at any point in the test case to suspend the test run at the current position for user input. ***Check Manual*** allows asking the tester a question. The question typically requests manual verification of an expected outcome. The answer will PASS or FAIL the test case, which is also reflected in the test report. diff --git a/atest/robotNL tests/01__Check that/Time constraints/01__Check within.robot b/atest/robotNL tests/01__Check that/Time constraints/01__Check within.robot new file mode 100644 index 0000000..be6c3cd --- /dev/null +++ b/atest/robotNL tests/01__Check that/Time constraints/01__Check within.robot @@ -0,0 +1,35 @@ +*** Settings *** +Resource base.resource + + +*** Test Cases *** +Single action passes within time span + Check that a delay of 10ms completes within 1 second + +Polling action passes within time span + Check that pass at the third attempt within 2 seconds + +Keyword passes, but too late + Run keyword and expect error *too late* + ... Check that a delay of 50ms completes within 10ms + +Single action fails after time span + ${message}= Run keyword and expect error CheckFailed* + ... Check that a delay of 200ms completes equals ${False} within 100ms + Check that ${message} does not contain text too late + +Polling action keeps failing within time span + Run keyword and expect error CheckFailed* + ... Check that Apple equals Pear within 100ms + +Time constraint from keyword + Run keyword and expect error *within 1/100th of a second [[]10 milliseconds[]] (too late)* + ... Check that a delay of 100ms completes within 1/100th of a second + +Invalid timespan text + Run keyword and expect error *Invalid time string 'the blink of an eye'. + ... Check that True within the blink of an eye + +Invalid timespan from keyword + Run keyword and expect error *Invalid time string 'My object'. + ... Check that True within not a timespan diff --git a/atest/robotNL tests/01__Check that/Time constraints/02__Check within same timespan.robot b/atest/robotNL tests/01__Check that/Time constraints/02__Check within same timespan.robot new file mode 100644 index 0000000..4064a22 --- /dev/null +++ b/atest/robotNL tests/01__Check that/Time constraints/02__Check within same timespan.robot @@ -0,0 +1,182 @@ +*** Settings *** +Resource base.resource + + +*** Test Cases *** +The first check in a suite cannot refer to 'same timespan' + TRY + Check that True within same timespan + EXCEPT Joint timespan expected, but was not set* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + +Two checks pass within joint time constraint + Check that a delay of 10ms completes within 100ms + Check that a delay of 10ms completes within same timespan + +Second check passes, but not within the joint time constraint + Check that a delay of 10ms completes within 100ms + TRY + Check postcondition a delay of 100ms completes within same timespan + EXCEPT *too late* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + +Setup new timespan to carry over to next test + Comment Setup only. Actual checks are executed in the next test. + Check that a delay of 10ms completes within 100ms + +A timespan can carry over to the next Test + [Documentation] Carry over of a timespan to the next test within a suite is + ... useful when you have an expensive action that has multiple asynchronous + ... results that you want to report and tag independently. + Comment Expects the running timespan from the previous test + Check that a delay of 10ms completes within same timespan + TRY + Check that a delay of 90ms completes within same timespan + EXCEPT *too late* type=GLOB + Comment Total delays add up to 110ms for the alotted 100ms. + ELSE + Fail Expected fail did not occur + END + +A check without time constraint does not end the running timespan + Check that a delay of 10ms completes within 100ms + Check that True + Check that a delay of 10ms completes within same timespan + +Timespans can be reused inside control structures + Check that a delay of 10ms completes within 100ms + FOR ${i} IN RANGE 2 + Check that a delay of 10ms completes within same timespan + END + +Checks after the timespan expired are executed exactly once + Reset counter + TRY + Check that ${False} within 10ms + EXCEPT CheckFailed* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + TRY + Check that counter increases, then pass within same timespan + EXCEPT *too late* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + Check that Counter value equals 1 + +Keywords do not affect the timespan of the Test + [Documentation] The keyword that separates the check that sets the timespan + ... from the one using it, sets a new timnespan internally of just 10ms. If + ... If the timespans are not properly separated, the second check will fail + ... as 'too late'. + Check that a delay of 10ms completes within 100ms + Keyword that uses a shorter check within + Check that a delay of 20ms completes within same timespan + +Keywords do not have access to the timespan of the calling test + Check that True within 100ms + TRY + Keyword that tries to use existing timespan + EXCEPT Joint timespan expected, but was not set* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + +Keywords do not affect the timespan of other keywords + Check that True within 50ms + Nested keyword that uses check within + TRY + Check that True within same timespan + EXCEPT *too late* type=GLOB + Comment Timespan already passed during the nested keyword + ELSE + Fail Expected fail did not occur + END + +Reporting shows the original timespan + Check that True within 10ms + TRY + Check that False within same timespan + EXCEPT *within 10ms* type=GLOB + Comment Note that the original text is kept, so '10ms' instead of the formatted '10 milliseconds' + ELSE + Fail Expected fail did not occur + END + +Reporting shows the original timespan including the keyword that produced it + Check that True within 1/100th of a second + TRY + Check that False within same timespan + EXCEPT *within 1/100th of a second [[]10 milliseconds[]]* type=GLOB + Comment Reports the keyword with its resulting value formatted between brackets + ELSE + Fail Expected fail did not occur + END + +Errors in timespan cancel the running timespan + Check that True within 10ms + TRY + Check that True within not a timespan + EXCEPT *Invalid time string 'My object'.* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + TRY + Check that True within same timespan + EXCEPT Joint timespan expected, but was not set* type=GLOB + No Operation + ELSE + Fail Expected fail did not occur + END + +Timespan is kept from the first instance + Check that a delay of 50ms completes within 100ms + Check that a delay of 10ms completes within same timespan + TRY + Check postcondition a delay of 50ms completes within same timespan + EXCEPT *too late* type=GLOB + Comment Would not have failed if the timer were reset at the first 'same timespan' + ELSE + Fail Expected fail did not occur + END + + +*** Keywords *** +Keyword that uses a shorter check within + Check that True within 10ms + +Keyword that tries to use existing timespan + Check that a delay of 10ms completes within same timespan + +Nested keyword that uses check within + Check that a delay of 10ms completes within 50ms + Keyword that uses a longer check within + TRY + Check that a delay of 50ms completes within same timespan + EXCEPT *too late** type=GLOB + Comment Would not have failed if the longer timespan were set + ELSE + Fail Expected fail did not occur + END + +Keyword that uses a longer check within + TRY + Check that a delay of 10ms completes within same timespan + EXCEPT Joint timespan expected, but was not set* type=GLOB + Comment Would not have failed if the calling keyword's timespan were accessable + ELSE + Fail Expected fail did not occur + END + Check that a delay of 10ms completes within 1 second + Check that a delay of 10ms completes within same timespan diff --git a/atest/robotNL tests/01__Check that/Time constraints/base.resource b/atest/robotNL tests/01__Check that/Time constraints/base.resource new file mode 100644 index 0000000..a1e3f71 --- /dev/null +++ b/atest/robotNL tests/01__Check that/Time constraints/base.resource @@ -0,0 +1,9 @@ +*** Settings *** +Resource ../base.resource +Library helper_keywords.py + + +*** Keywords *** +a delay of ${timespan} completes + Sleep ${timespan} + RETURN ${True} diff --git a/atest/robotNL tests/01__Check that/Time constraints/helper_keywords.py b/atest/robotNL tests/01__Check that/Time constraints/helper_keywords.py new file mode 100644 index 0000000..37494f0 --- /dev/null +++ b/atest/robotNL tests/01__Check that/Time constraints/helper_keywords.py @@ -0,0 +1,42 @@ +from robot.api.deco import library, keyword + + +@library +class helper_keywords: + def __init__(self): + self.gen = self._fail_fail_pass_generator() + self.counter = 0 + + @staticmethod + def _fail_fail_pass_generator(): + yield False + yield False + yield True + + @keyword("Pass at the third attempt") + def pass_at_third_attempt(self): + return next(self.gen) + + @keyword("Reset counter") + def reset_counter(self): + self.counter = 0 + + @keyword("counter increases, then pass") + def plus_counter(self): + self.counter += 1 + return True + + @keyword("counter value") + def counter_value(self): + return self.counter + + @keyword("1/100th of a second") + def timespan_keyword(self): + return '0.01 sec' + + @keyword("Not a timespan") + def return_object(self): + class MyObject: + def __str__(self): + return 'My object' + return MyObject() diff --git a/docs/robotnl-libdoc.html b/docs/robotnl-libdoc.html index f0596b0..027d513 100644 --- a/docs/robotnl-libdoc.html +++ b/docs/robotnl-libdoc.html @@ -1,1876 +1,387 @@ - - - - - - - - - - - - - - - - - - - - + + + + + + + - + - -
-

Opening library documentation failed

- + + +
+

Opening library documentation failed

+
- - - - function clearTagSearch() { - document.getElementsByClassName('search-input')[0].value = ''; - history.replaceState && history.replaceState(null, '', window.location.pathname); - resetKeywords(); - } + + + + - function closeMenu() { - document.getElementById('hamburger-menu-input').checked = false; - } - - function markMatches(pattern, include, givenSearchTime, callback) { - if (givenSearchTime && givenSearchTime !== searchTime) { - return; - } - let patternRegexp = util.regexpEscape(pattern); - if (include.tagsExact) { - patternRegexp = '^' + patternRegexp + '$'; - } - let regexp = new RegExp(patternRegexp, 'i'); - let test = regexp.test.bind(regexp); - let result = {}; - let keywordMatchCount = 0; - result.keywords = util.map(libdoc.keywords, function (kw) { - kw = $.extend({}, kw); - kw.hidden = !(include.name && test(kw.name)) && - !(include.args && test(kw.args)) && - !(include.doc && test($(kw.doc).text())) && - !(include.tags && util.any(util.map(kw.tags, test))); - if (!kw.hidden) - keywordMatchCount++; - return kw; - }); - renderTemplate('keyword-shortcuts', result); - renderTemplate('keywords', result); - if (libdoc.tags.length) { - libdoc.selectedTag = include.tagsExact ? pattern : ""; - renderTemplate('tags-shortcuts', libdoc); - } - document.getElementById("keyword-statistics-header").innerText = keywordMatchCount + ' / ' + result.keywords.length; - if (keywordMatchCount === 0) - $('#keywords-container').find('table').empty(); - if (callback) { - requestAnimationFrame(callback); - } - } - - function highlightMatches(string, include, givenSearchTime) { - if (givenSearchTime && givenSearchTime !== searchTime) { - return; - } - const shortcuts = $('#shortcuts-container').find('.match'); - const keywords = $('#keywords-container').find('.match'); - if (include.name) { - shortcuts.highlight(string); - keywords.find('.kw').highlight(string); - } - if (include.args) { - keywords.find('.args').highlight(string); - } - if (include.doc) { - keywords.find('.doc').highlight(string); - } - if (include.tags) { - var matches = keywords.find('.tags').find('a').add( - $('#tags-shortcuts-container').find('a')); - if (include.tagsExact) { - matches = matches.filter(function (index, tag) { - return $(tag).text().toUpperCase() === string.toUpperCase(); - }); - } - matches.highlight(string); - } - } - - function clearSearch() { - document.getElementsByClassName('search-input')[0].value = ''; - const tagsSelect = document.getElementById('tags-shortcuts-container'); - if (tagsSelect) { - tagsSelect.selectedIndex = 0; - } - resetKeywords(); - } - - let searchTime = 0; - - function searching() { - searchTime = Date.now(); - const value = document.getElementsByClassName('search-input')[0].value; - const include = {name: true, - args: true, - doc: true, - tags: true}; - if (value) { - requestAnimationFrame(function () { - markMatches(value, include, searchTime, - function () { - highlightMatches(value, include, searchTime); - document.getElementById('keyword-shortcuts-container').scrollTop = 0; - } - ); - }); - } else { - resetKeywords(); - } - } - - function toggleShortcuts() { - const shortcuts = document.getElementsByClassName("shortcuts")[0]; - if (shortcuts.classList.contains("keyword-wall")) { - closeKeywordWall(); - } else { - openKeywordWall(); - } - } - - function openKeywordWall() { - const shortcuts = document.getElementsByClassName("shortcuts")[0]; - shortcuts.classList.add("keyword-wall"); - storage.set("keyword-wall", 'open'); - const button = document.getElementById("toggle-keyword-shortcuts") - button.innerText = '-'; - } - - function closeKeywordWall() { - const shortcuts = document.getElementsByClassName("shortcuts")[0]; - shortcuts.classList.remove("keyword-wall"); - storage.set("keyword-wall", 'close'); - const button = document.getElementById("toggle-keyword-shortcuts") - button.innerText = '+'; - } - - function resetKeywords() { - renderTemplate('keyword-shortcuts', libdoc); - renderTemplate('keywords', libdoc); - renderTemplate('data-types', libdoc); - if (libdoc.tags.length) { - renderTemplate('tags', libdoc); - } - document.getElementById("keyword-statistics-header").innerText = ''+libdoc.keywords.length; - if (libdoc.typedocs.length) { - document.getElementById("type-statistics-header").innerText = '' + libdoc.typedocs.length; - } - history.replaceState && history.replaceState(null, '', location.pathname); - } - - function createModal() { - const modalBackground = document.createElement('div'); - modalBackground.id = 'modal-background'; - modalBackground.classList.add('modal-background'); - modalBackground.addEventListener('click', ({ target }) => { - if (target.id === 'modal-background') hideModal() - }) - - const modalCloseButton = document.createElement('button'); - modalCloseButton.innerHTML = ` - `; - modalCloseButton.classList.add('modal-close-button'); - const modalCloseButtonContainer = document.createElement('div'); - modalCloseButtonContainer.classList.add('modal-close-button-container'); - modalCloseButtonContainer.appendChild(modalCloseButton); - modalCloseButton.addEventListener('click', () => { - hideModal() - }) - modalBackground.appendChild(modalCloseButtonContainer); - modalCloseButtonContainer.addEventListener('click', () => { - hideModal() - }) - - const modal = document.createElement('div'); - modal.id = 'modal'; - modal.classList.add('modal'); - modal.addEventListener('click', ({ target }) => { - if (target.tagName.toUpperCase() === 'A') hideModal() - }) - - - const modalContent = document.createElement('div'); - modalContent.id = 'modal-content'; - modalContent.classList.add('modal-content'); - modal.appendChild(modalContent); - - modalBackground.appendChild(modal); - document.body.appendChild(modalBackground); - document.addEventListener('keydown', ({ key }) => { - if (key === 'Escape') hideModal() - }) - } - function showModal(content) { - const modalBackground = document.getElementById('modal-background'); - const modal = document.getElementById('modal'); - const modalContent = document.getElementById('modal-content'); - modalBackground.classList.add('visible'); - modal.classList.add('visible'); - modalContent.appendChild(content.cloneNode(true)); - document.body.style.overflow = 'hidden'; - } - function hideModal() { - const modalBackground = document.getElementById('modal-background'); - const modal = document.getElementById('modal'); - const modalContent = document.getElementById('modal-content'); - - modalBackground.classList.remove('visible'); - modal.classList.remove('visible'); - document.body.style.overflow = 'auto'; - if (window.location.hash.indexOf('#type-') == 0) - history.pushState("", document.title, window.location.pathname); - // modal is hidden with a fading transition, timeout prevents premature emptying of modal - setTimeout(() => { - modalContent.innerHTML = ''; - }, 200); - } - - // http://stackoverflow.com/a/18484799 - var delay = (function () { - var timer = 0; - return function(callback, ms) { - clearTimeout(timer); - timer = setTimeout(callback, ms); - }; - })(); +
+ - - - - - - - - - - - - - - - - - + + - - - - + - - - - diff --git a/pyproject.toml b/pyproject.toml index 9a823b9..f86ae13 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -7,7 +7,7 @@ build-backend = "setuptools.build_meta" [project] name = "robotframework-nl" -version = "3.1.0" +version = "3.2.0" description = "robotnl is a proving ground to boost Robot framework closer to Natural Language." readme = "README.md" authors = [{ name = "Johan Foederer", email = "github@famfoe.nl" }] diff --git a/robotnl/RobotChecks.py b/robotnl/RobotChecks.py index 6a9ee3a..0b9a213 100644 --- a/robotnl/RobotChecks.py +++ b/robotnl/RobotChecks.py @@ -48,7 +48,25 @@ class CheckFailed(RuntimeError): class RobotChecks: ROBOT_LIBRARY_SCOPE = "GLOBAL" def __init__(self): + self.ROBOT_LIBRARY_LISTENER = self self.__gui = None + self.scope_depth = 0 + self.nested_timespans = {} + + def _start_suite(self, data, result): + self.scope_depth = 0 + self.nested_timespans = {} + _end_suite = _start_suite + + def _start_keyword(self, data, result): + self.scope_depth += 1 + + def _end_keyword(self, data, result): + if self.scope_depth + 1 in self.nested_timespans: + # use depth+1 because 'check that' itself is also a keyword. The +1 + # keeps all check thats on the same level grouped. + self.nested_timespans.pop(self.scope_depth + 1) + self.scope_depth -= 1 @property def _gui(self): @@ -74,7 +92,7 @@ def check_precondition(self, *args): point where it was able to check the requirement it was testing for. """ try: - return RobotChecks.__execute_check("Precondition", *args) + return self.__execute_check("Precondition", *args) except CheckFailed as failure: failure.ROBOT_CONTINUE_ON_FAILURE = False raise failure @@ -91,7 +109,7 @@ def check_postcondition(self, *args): the cause of failure. """ try: - return RobotChecks.__execute_check("Postcondition", *args) + return self.__execute_check("Postcondition", *args) except CheckFailed as failure: failure.ROBOT_CONTINUE_ON_FAILURE = False raise failure @@ -108,16 +126,19 @@ def check_that(self, *args): Check that has two basic forms. - A single keyword (with its arguments) can be evaluated to a truth value - Two values or keywords (with their arguments) can be evaluated using an operator. It will - then have the form Check that ```` ```` ````. + then have the form: Check that ```` ```` ````. - Operator can be any Robot keyword taking exactly two values (left and right operands) as - input. A number of predefined operators on numeric, string and list types are included in - this library. + Operator can be any Robot keyword taking at least one argument as input. The first argument is + placed on the left side of the operator, the left operand. Any following arguments are placed + to the right of the operator and form the right operands. A keyword with its argument values is + treated as a single operand. A number of predefined operators on numeric, string and list types + are included in this library. Examples: | `Check that` | 3 | `=` | 3 | | `Check that` | _Two times_ | 6 | `equals` | 12 | | `Check that` | _Two times_ | 5 | `≠` | _Two times_ | 7 | + | `Check that` | _the shoe box_ | _contains 2 items_ | | `Check that` | _Earth exists_ | 'Two times' in these examples is assumed to be defined as a Robot keyword that takes one @@ -129,16 +150,25 @@ def check_that(self, *args): This will cause the condition to be reevaluated until it becomes true, or until the specified time has passed. In the latter case the test case will fail. + Multiple checks can be linked to the same time constraint by using ``same timespan`` + as the time contraint value. Suppose the previous time contraint was 5 seconds and + that check took 2 seconds to complete. If the next check uses + ``within same timespan``, then this check has the remaing 3 seconds to complete. + Example with time constraint: | `Check that` | _condition is true_ | within | 1 minute 30 seconds | Elevator example: - | `Check that` | _elevator doors are closed_ | | _Request elevator at floor_ | 3 | - | `Check that` | _elevator floor_ | `equals` | 3 | within | 20 seconds | - | `Check that` | _offset to floor level in mm_ | `≤` | 5 | within | 3 seconds | + | `Check that` | _elevator doors are closed_ | within | 20 seconds | + | `Check that` | _elevator floor_ | `equals` | 3 | within | 1 minute | + | `Check that` | _elevator doors are opened_ | within | same timespan | + + In the elevator example, the doors should be closed within 20 seconds after requesting a + floor. Then the elevator can take a maximum of 1 minute to reach the floor and open its + doors. `Check that` will continue as soon as the condition is detected. """ - return RobotChecks.__execute_check("Requirement", *args) + return self.__execute_check("Requirement", *args) RUN_KW_REGISTER.register_run_keyword('robotnl', check_that.__name__, args_to_process=0, deprecation_warning=False) def check_manual(self, checkRequestText=""): @@ -210,8 +240,7 @@ def check_interactive(self): except Exception as e: BuiltIn().log_to_console("Error in interactive keyword '%s'\n\n%s" % (newInput, e)) - @staticmethod - def __execute_check(checkType, *args): + def __execute_check(self, checkType, *args): """ Parse arguments for check keyword to determine its operands, evaluate them and execute the check. @@ -223,14 +252,35 @@ def __execute_check(checkType, *args): TimeOutInSeconds = 0 TimeRemaining = True s_TimeConstraint = "" + StartTime = time.perf_counter() if len(Arguments) >= 2 and str(Arguments[-2]).lower() == 'within': - EvaluatedTimeArg = RobotChecks.__evaluateOperand([Arguments[-1]])[0] - TimeOutInSeconds = timestr_to_secs(EvaluatedTimeArg) - s_TimeConstraint = Arguments[-1] + timearg = Arguments[-1] Arguments = Arguments[:-2] + running_timespan_start, running_timespan, s_TimeConstraint =self.nested_timespans.get( + self.scope_depth, (None, None, '')) + if str(timearg).lower() == 'same timespan': + if running_timespan is None: + BuiltIn().fail("Joint timespan expected, but was not set before this check.") + TimeOutInSeconds = round(running_timespan_start + running_timespan - StartTime, ndigits=3) + + remaining = self._human_time(0 if TimeOutInSeconds < 0 else TimeOutInSeconds) + BuiltIn().log(f"Reusing joint timespan: {s_TimeConstraint}\n" + f"Must complete within the remaining {remaining}") + else: + try: + EvaluatedTimeArg, s_TimeConstraint = RobotChecks.__evaluateOperand([timearg]) + TimeOutInSeconds = timestr_to_secs(EvaluatedTimeArg) + except: + # End any running timespan on error + if self.scope_depth in self.nested_timespans: + self.nested_timespans.pop(self.scope_depth) + raise + if is_keyword(timearg): + s_TimeConstraint = f"{timearg} [{secs_to_timestr(TimeOutInSeconds)}]" + self.nested_timespans[self.scope_depth] = (StartTime, TimeOutInSeconds, s_TimeConstraint) if not len(Arguments): - BuiltIn().fail("%s check failed. There was nothing to check." % checkType) + BuiltIn().fail(f"{checkType} check failed. There was nothing to check.") ############################################################################################ # Build expression @@ -263,8 +313,6 @@ def __execute_check(checkType, *args): # Evaluate expression EvaluatedResult = None - StartTime = time.perf_counter() - TimeLeft = TimeOutInSeconds PollMax = 20 # After 20s people start wondering: "Is it still going?" Time for an update. PollMin = min(PollMax/8, TimeOutInSeconds*3/100) # Shortest delay is 3% of the target time. PollDelay = PollMin # Initial poll delay will be 2x PollMin @@ -312,8 +360,14 @@ def __execute_check(checkType, *args): ReportString = f"{checkType} check on '{s_LeftOperand} {OperatorKeyword} {s_RightOperand}'" if s_TimeConstraint: - ReportString += " within %s" % secs_to_timestr(TimeOutInSeconds) + running_start, timespan, timestr = self.nested_timespans.get(self.scope_depth, (None, None, '')) + if TimeRemaining and running_start != StartTime: + elapsed = time.perf_counter() - running_start + BuiltIn().log(f"Check completed {self._human_time(elapsed)} into the alotted timespan ({timestr})") + ReportString += f" within {timestr}" if not TimeRemaining and EvaluatedResult == "passed": + overshoot = time.perf_counter() - (running_start + timespan) + BuiltIn().log(f"Check completed {self._human_time(overshoot)} too late") ReportString += " (too late)" raise CheckFailed(ReportString) @@ -356,3 +410,10 @@ def __evaluateOperand(operand): s_Operand += f" [{s_Value}]" return Value, s_Operand + + @staticmethod + def _human_time(time_in_seconds: float): + """return a human readable string for a time in seconds""" + SKIP_MILLI = 10 # Do not report milliseconds for timespans above SKIP_MILLI seconds + rounded_time = int(time_in_seconds) if time_in_seconds > SKIP_MILLI else round(time_in_seconds, ndigits=3) + return secs_to_timestr(rounded_time) diff --git a/robotnl/version.py b/robotnl/version.py index 59a2fe6..11ad25d 100644 --- a/robotnl/version.py +++ b/robotnl/version.py @@ -1 +1 @@ -VERSION = '3.1.0' +VERSION = '3.2.0'