Skip to content

ExecutionResult is returning a wrong start_time, end_time and elapsed. #5142

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
joseajunior opened this issue Jun 6, 2024 · 11 comments
Closed

Comments

@joseajunior
Copy link

I'm trying to parse a xml file to upload some data to a db using DbBot.
But after the upload, the results don't show the right start_time, end_time and elapsed.

I manually ran the ExecutionResult into the output.xml and started printing the start_time and end_time for each level of suite.
Until I got to a point where the suite had several subsuites and was where I really see the time difference, where the subsuite startime was higher than the root's suite endtime.

result = ExecutionResult('<xml_path>')
print(f'{result.suite.name}: {result.suite.starttime}') # WexEdge: 20240514 20:49:27.760
print(f'{result.suite.name}: {result.suite.endtime}') # WexEdge: 20240514 20:53:37.283
print(f'{result.suite.suites[0].name}: {result.suite.suites[0].starttime}') # UI: 20240514 20:49:27.925
print(f'{result.suite.suites[0].name}: {result.suite.suites[0].endtime}') # UI: 20240514 20:53:37.241
print(f'{result.suite.suites[0].suites[0].name}: {result.suite.suites[0].suites[0].starttime}') # Tests: 20240514 20:49:27.936
print(f'{result.suite.suites[0].suites[0].name}: {result.suite.suites[0].suites[0].endtime}') # Tests: 20240514 20:53:37.240
print(f'{result.suite.suites[0].suites[0].suites[0].name}: {result.suite.suites[0].suites[0].suites[0].starttime}') # Gold Customer: 20240514 20:49:27.940
print(f'{result.suite.suites[0].suites[0].suites[0].name}: {result.suite.suites[0].suites[0].suites[0].endtime}') # Gold Customer: 20240514 20:53:37.232
print(f'{result.suite.suites[0].suites[0].suites[1].name}: {result.suite.suites[0].suites[0].suites[1].starttime}') # Gold Sales: 20240514 20:49:28.638
print(f'{result.suite.suites[0].suites[0].suites[1].name}: {result.suite.suites[0].suites[0].suites[1].endtime}') # Gold Sales: 20240514 20:52:13.466
print(f'{result.suite.suites[0].suites[0].suites[2].name}: {result.suite.suites[0].suites[0].suites[2].starttime}') # Wex Edge: 20240514 20:55:23.514
print(f'{result.suite.suites[0].suites[0].suites[2].name}: {result.suite.suites[0].suites[0].suites[2].endtime}') Wex Edge: 20240514 20:56:23.631

RF version: robotframework==7.0

XML file: Drive link

And in the report.html it says that the elapsed time was: 01:48:12
Screenshot 2024-06-06 at 17 43 05

@pekkaklarck
Copy link
Member

Could you please clarify the issue? Which exact numbers were not as expected? Did you get output.xml directly from execution or have you used the Rebot tool to merge, combine or otherwise modify it?

@joseajunior
Copy link
Author

From what I imagine, the start_time, end_time, and elapsed time from the root suite should be the same as the one on the report.html, right?

The report was created using Pabot.

@pekkaklarck
Copy link
Member

Can you show where the values in output.xml and report.html differ? Notice that your original example only shows start/end times.

Notice that All Tests in log and report statistics only contain information about tests. In that elapsed time the time taken by possible suite setup and teardown is not visible. To see the actual elapsed time of a suite, you need to look at suite information.

Pabot uses the Rebot tool internally to combine results of the individual suites (or tests) that have been executed parallel. How exactly it uses Rebot may affect the results. If you suspect there's a bug in Robot, you need to be able to demonstrate it without Pabot. If you suspect there's a bug in Pabot, you need to submit an issue to its issue tracker.

@joseajunior
Copy link
Author

Okay, so I ran the same tests just with Robot, and the elapsed time from result.suite.elapsed_time was 0:17:18.786542 while the one from the log.html was 00:16:44.

With that, I believe the issue (if there is one) is on Pabot.
But now I have some questions:

  1. This ~26 seconds difference is okay because it doesn't track the setups and teardowns, right?
  2. How can I get the All Tests elapsed time?
  3. For my DbBot/Grafana dashboard, how can I get an accurate start_time, end_time, and elapsed_time using the ExecutionResult ?

@pekkaklarck
Copy link
Member

What time in the log file is that 00:16:44? If result.suite.elapsed_time is 0:17:18.786542, the elapsed time of the top level suite in the log file should be exactly that rounded to milliseconds. As I already mentioned, All Tests time doesn't contain suite setups and teardowns and is thus typically different.

If there isn't a bug somewhere, it would be better to start a discussion about this on our Slack or Forum. This issue tracker is for bug reports and concrete enhancement requests.

@joseajunior
Copy link
Author

I am closing this here and moving to pabot.

@joseajunior joseajunior closed this as not planned Won't fix, can't repro, duplicate, stale Sep 16, 2024
@joseajunior
Copy link
Author

Reopening this issue according to comment in mkorpela/pabot#596

@joseajunior joseajunior reopened this Dec 13, 2024
@pekkaklarck
Copy link
Member

Could you please clarify what the problem is? Please also see my earlier comment.

@joseajunior
Copy link
Author

Quoting @mkorpela in the pabot issue: "the parent suite's endtime is earlier than some child suites' endtimes, which shouldn't be possible in a properly constructed test execution result"
This is causing that the root Suite has a endtime and elapsed time lower than some of their child suites.
I added a zip file there with some more recent reports.

Hope I answered you question Pekka.

@pekkaklarck
Copy link
Member

No, that doesn't answer my question. I understand your quote, but you need to provide concrete example of such a problem. A concrete example demonstrating the problem would be helpful, but it needs to be as simple as possible.

@pekkaklarck
Copy link
Member

No new information so closing. Can be reopened if there's an example demonstrating the issue.

@pekkaklarck pekkaklarck closed this as not planned Won't fix, can't repro, duplicate, stale May 20, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants