768239 - Add progress indicator for [current/total] test count to Mozmill output

Status: RESOLVED WONTFIX

(Testing Graveyard :: Mozmill, defect)

Description

[Dave Hunt [:davehunt] [he/him] ⌚BST]

It would be useful to give an indication of the number of tests that have run, and how many tests will run in total. This could be in the console output, or presented in the application under test.

Comment 1

[Juan C. Mojica Roa (:jcmojicar)]

Hi, i would like to work on this. You think that having an output like this will do it?

RESULTS | Total Tests to be Executed: 7
RESULTS | Passed: 6
RESULTS | Failed: 0
RESULTS | Skipped: 1
RESULTS | Total Tests Executed: 7

Or you were thinking on giving and indication like the following after every test is ran?:

Test 1 of 7
....
Test 2 of 7
....
Test 3 of 7

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Hi jcmojicar, it would be indeed great if you can help. We have seen lately that we somehow miss to run some tests especially for restart tests. So having this output would be great.

I don't think we need a constant output of 1/2 ... 7/7, but the final line should show something like:

RESULTS | Tests executed 6/6

So I think skipped tests shouldn't be accounted for. Dave, what do you think?

Comment 3

[Andrei Eftimie]

My 2 cents on this issue:
- we should take all tests into consideration
- the final output should contain the total (Passed + Skipped + Failed)

We might want to know even if a skipped test has been completely missed and we don't have any report in it.

Comment 4

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Actually, the point of this bug was to indicate a progress rather than alter the final summary. While tests are currently running there is no indication of how far through the test suite you are. Total test counts are easily calculated from the existing summary. Something like [1/7] etc would work for me.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Oh, ok. Then yes, that's something else. Updating the summary accordingly. Juan do you still have interest working on it? I hope so. :)

Comment 6

[Juan C. Mojica Roa (:jcmojicar)]

Sure i do.

So, going for the two approaches. Current indicator (1/7....7/7) and a line for the totals in the final summary.

Comment 7

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to jcmojicar from comment #6)
> Sure i do.
> 
> So, going for the two approaches. Current indicator (1/7....7/7) and a line
> for the totals in the final summary.

No need for changing the final summary. This is just for the progress indicator.

Comment 8

[Juan C. Mojica Roa (:jcmojicar)]

This what i have done to try to get the desired behaviour:

In logger.py:

1- Added a new custom level in self.custom_levels. PROGRESS: 900

2- Added a new event in events(), mozmill.logProgress : self.logProgress

3- Added a new function logProgress that prints the current test and the total tests.

4- Assigned CYAN color to PROGRESS

In mozmill __init__.py:

1- In MozMill.run(), added a counter to keep track of the tests being run.

2- Invoke the logging module by calling handlers.logProcess (as done when the finish() method is called).

The total amount of tests is taken from the length of the tests array passed to the MozMill run() method.

The current test is taken from the counter (inside the while loop that goes through the tests list).


This will produce an output like the following:

PROGRESS | Test 1 out of 7
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | setupModule
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | testScrollBackgroundTabIntoView
TEST-PASS | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | testScrollBackgroundTabIntoView
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | teardownModule
TEST-END | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | finished in 6090ms
PROGRESS | Test 2 out of 7
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | setupModule
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | testCloseTab
TEST-PASS | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | testCloseTab
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | teardownModule
TEST-END | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | finished in 1868ms

.
.
.


Is something like this the desired behaviour?.

Comment 9

[Dave Hunt [:davehunt] [he/him] ⌚BST]

This looks good to me. I would suggest using INFO instead of a custom log level, and would change the message to "Running test X of Y". Let's see what Henrik thinks, although he's on PTO at the moment so he likely won't respond until next week.

Comment 10

[Juan C. Mojica Roa (:jcmojicar)]

I have changed it to use INFO logging level, the custom one was erased. I also think is better this way. The text of the message was updated. So far it looks like this:

INFO | Running Test 1 of 7
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | setupModule
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | testScrollBackgroundTabIntoView
TEST-PASS | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | testScrollBackgroundTabIntoView
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | teardownModule
TEST-END | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | finished in 11897ms
INFO | Running Test 2 of 7
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testCloseTab.js | setupModule

Comment 11

[Dave Hunt [:davehunt] [he/him] ⌚BST]

The sample output looks good to me. Feel free to get a patch up for review. :)

Comment 12

[Juan C. Mojica Roa (:jcmojicar)]

Attachment: Patch - Add a progress indicator for test count

Comment 13

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8384356 [details] [diff] [review]
Patch - Add a progress indicator for test count

Review of attachment 8384356 [details] [diff] [review]:
-----------------------------------------------------------------

Providing feedback, and switching review to Henrik for his thoughts.

::: mozmill/mozmill/__init__.py
@@ +231,4 @@
>                            eventType='mozmill.setTest')
>          self.add_listener(self.shutdown_listener,
>                            eventType='mozmill.shutdown')
> +        self.add_listener(self.logProgress_listener,

Rather than introduce a new listener, I would explore using the existing startTest listener to include the progress logging.

@@ +285,4 @@
>          # event listeners
>          for callback in self.listener_dict.get(event, []):
>              callback(obj)
> +   

Please ensure there is no superfluous white space in your patches.

@@ +406,4 @@
>  
>              # run tests
>              tests = list(tests)
> +            total_tests = len(tests)

I would just use len(tests) below instead of storing this value.

@@ +406,5 @@
>  
>              # run tests
>              tests = list(tests)
> +            total_tests = len(tests)
> +            curr_test_indx = 1

Please expand to current_test or current_test_index

@@ +429,4 @@
>                      }
>                      self.fire_event('endTest', obj)
>                      continue
> +                

As above regarding white space.

@@ +450,4 @@
>                      frame = None
>                      self.handle_disconnect()
>  
> +                curr_test_indx = curr_test_indx + 1

Use curr_test_idx += 1

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Personally I would drop the 'of' and show it like '[7 / 14]'.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8384356 [details] [diff] [review]
Patch - Add a progress indicator for test count

Review of attachment 8384356 [details] [diff] [review]:
-----------------------------------------------------------------

This looks already fine. I have some additional comments to those Dave already gave. Please see my inline comments for more details.

::: mozmill/mozmill/__init__.py
@@ +231,4 @@
>                            eventType='mozmill.setTest')
>          self.add_listener(self.shutdown_listener,
>                            eventType='mozmill.shutdown')
> +        self.add_listener(self.logProgress_listener,

That will not work because that will fire for each individual test inside a test module. What we really need here is setModule. Interestingly we don't have a specific listener for that yet, and also don't send an appropriate event from frame.js similar to endModule:

https://github.com/mozilla/mozmill/blob/master/mozmill/mozmill/extension/resource/modules/frame.js#L224

We should better get this implemented.

@@ +431,5 @@
>                      continue
> +                
> +                for handler in self.handlers:
> +                    if hasattr(handler, 'logProgress'):
> +                        handler.logProgress(curr_test_indx, total_tests)

By using 'setModule' we wouldn't need that but then we also have to figure out how to pass the number of tests and the current index to the logger.

Comment 16

[Juan C. Mojica Roa (:jcmojicar)]

Attachment: 0001-Fixed-Review-Comments.patch

Changes according to some comments of the review

Comment 17

[Juan C. Mojica Roa (:jcmojicar)]

(In reply to Dave Hunt (:davehunt) from comment #13)
> Comment on attachment 8384356 [details] [diff] [review]
> Patch - Add a progress indicator for test count
> 
> Review of attachment 8384356 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Providing feedback, and switching review to Henrik for his thoughts.
> 
> ::: mozmill/mozmill/__init__.py
> @@ +231,4 @@
> >                            eventType='mozmill.setTest')
> >          self.add_listener(self.shutdown_listener,
> >                            eventType='mozmill.shutdown')
> > +        self.add_listener(self.logProgress_listener,
> 
> Rather than introduce a new listener, I would explore using the existing
> startTest listener to include the progress logging.
> 

Changed accordingly, got the logProgress listener removed (it was not used anyway).

> @@ +285,4 @@
> >          # event listeners
> >          for callback in self.listener_dict.get(event, []):
> >              callback(obj)
> > +   
> 
> Please ensure there is no superfluous white space in your patches.
> 
> @@ +406,4 @@
> >  
> >              # run tests
> >              tests = list(tests)
> > +            total_tests = len(tests)
> 
> I would just use len(tests) below instead of storing this value.
> 

This will not work. The tests list got modified with .pop(0) inside the while loop that executes the tests.

> @@ +406,5 @@
> >  
> >              # run tests
> >              tests = list(tests)
> > +            total_tests = len(tests)
> > +            curr_test_indx = 1
> 
> Please expand to current_test or current_test_index
> 

Expanded to current_test_index, current_test is used somewhere else in the code.

> @@ +429,4 @@
> >                      }
> >                      self.fire_event('endTest', obj)
> >                      continue
> > +                
> 
> As above regarding white space.
> 
> @@ +450,4 @@
> >                      frame = None
> >                      self.handle_disconnect()
> >  
> > +                curr_test_indx = curr_test_indx + 1
> 
> Use curr_test_idx += 1

 Changed to current_test_index += 1

Comment 18

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8386502 [details] [diff] [review]
0001-Fixed-Review-Comments.patch

Review of attachment 8386502 [details] [diff] [review]:
-----------------------------------------------------------------

This is an incomplete patch - please recreate this patch based on the master branch with no other patches applied and request review/feedback again.

Comment 19

[Juan C. Mojica Roa (:jcmojicar)]

Attachment: 0001-Fixed-Review-Comments.patch

I think i got it this time, i merged the previous commits into one before generating the patch.

There is one white line i could not get rid of. In the code it looks normal.

Comment 20

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8387356 [details] [diff] [review]
0001-Fixed-Review-Comments.patch

Review of attachment 8387356 [details] [diff] [review]:
-----------------------------------------------------------------

In comment 15, Henrik points out that this will fire for every test within a test module, which means we will end up with current_test being greater that total_tests. I'll leave Henrik to comment further if you need some help with his suggestion of using a setModule listener.

::: mozmill/mozmill/__init__.py
@@ +283,4 @@
>          # event listeners
>          for callback in self.listener_dict.get(event, []):
>              callback(obj)
> +   

You've introduced whitespace here. Any blank lines need to be completely empty with no tabs or spaces.

@@ +422,4 @@
>                      }
>                      self.fire_event('endTest', obj)
>                      continue
> +                

As above, please make sure there are no spaces or tabs on blank lines.

::: mozmill/mozmill/logger.py
@@ +260,4 @@
>          self.logger.log(self.custom_levels["TEST-END"],
>                          "%s | finished in %dms" % (filename, duration))
>  
> +    def logProgress(self, curr_test, totaltests):

The arguments here should be current_test and total_tests.

Comment 21

[Juan C. Mojica Roa (:jcmojicar)]

Attachment: 0001-Fixed-Review-Comments-Eliminate-white-spaces.patch

I removed the white spaces in the blank lines, thanks for the tip.

As it is right now, this is calling the logProgress listener in logger.py for every .js file passed as parameter to mozmill. So far in the tests it has never showed a bigger number than the actual amount of tests executed, also in the the mozmill output you can see that the INFO message with the progress information is shown once before the setupModule message and not for every test ran inside the module.

If you and Henrik think this solution is better implemented with a setupModule listener and a call to this listener from frame.js as Henrik commented i could work on it.

Comment 22

[Dave Hunt [:davehunt] [he/him] ⌚BST]

Comment on attachment 8388022 [details] [diff] [review]
0001-Fixed-Review-Comments-Eliminate-white-spaces.patch

Review of attachment 8388022 [details] [diff] [review]:
-----------------------------------------------------------------

Patch looks much cleaner now, thanks. I'll now leave it for Henrik to review and comment.

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8388022 [details] [diff] [review]
0001-Fixed-Review-Comments-Eliminate-white-spaces.patch

Review of attachment 8388022 [details] [diff] [review]:
-----------------------------------------------------------------

I really want to see the use of setupModule here, given that this really indicates that a test has been started. Otherwise we have wrong information in the index. Also with this event the for loop should not be necessary, and we could more easily calculate the duration of a test module.

::: mozmill/mozmill/__init__.py
@@ +404,1 @@
>              while tests:

nit: Please add a blank line above.

Comment 24

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Juan, would you mind giving us an update for the status of this bug? Are you still interested to get it fixed? Please let us know. Thanks.

Comment 25

[Juan C. Mojica Roa (:jcmojicar)]

Hello Henrik, yes sure im still interested, have not had time to work on it, was on vacations and getting married. I will give an update the next week. Sorry for the delay.

Comment 26

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Wow, great news! So congrats for that! :) I totally understand your break then. Your plan sounds fine, thanks for the feedback.

Comment 27

[Juan C. Mojica Roa (:jcmojicar)]

Attachment: 0001-Bug-768239-Added-Test-Progress-setupModule-Event.patch

The test progress looks like requested:

INFO | Running Test [1 / 7]
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | setupModule
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testBackgroundTabScrolling.js | testScrollBackgroundTabIntoView

.
.
.

TEST-END | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testOpenInForeground.js | finished in 797ms
INFO | Running Test [7 / 7]
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testTabPinning.js | setupModule
TEST-START | /home/jcmojica/mozmill-tests/firefox/tests/functional/testTabbedBrowsing/testTabPinning.js | testTabPinning

but this time the current test index is increased only when the setupModule event is called. The setupModule behaviour is the same as the setTest one, is called from frame.js, then the listener in __init__.py and then the listener in logger.py is called.

Please let me know about any comments.

Comment 28

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Juan, I'm totally sorry but this review request totally got under the wire. Not sure how I missed that all the time. I will do a review in a bit.

Comment 29

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Comment on attachment 8410053 [details] [diff] [review]
0001-Bug-768239-Added-Test-Progress-setupModule-Event.patch

Review of attachment 8410053 [details] [diff] [review]:
-----------------------------------------------------------------

Juan, the patch doesn't apply cleanly anymore given that it was sitting around that long. There are a couple of things which would also have to be changed. But before I want to call them out, I have a question to you. Would you still be interested to work on this? I ask because Mozmill reaches its end of life soon, and we are trying to get the remaining issues fixed. If you are interested to work on something else, that would make more sense. Please let me know. 

Thanks, and really sorry again for the silence here.

::: mozmill/mozmill/__init__.py
@@ +196,4 @@
>          self.persisted['screenshots']['path'] = screenshots_path or tempfile.mkdtemp()
>  
>          # setup event handlers and register listeners
> +        self.test_current_index = 1

This is not a handler nor listener. I think you better want to add it at the beginning of the run method. That way the index also gets reset if run() is called multiple times in a row.

Comment 30

[Henrik Skupin [:whimboo][⌚️UTC+2]]

No reply for 8 months. So I assume you are no longer working on this bug. I'm going to close this bug given that Mozmill got deprecated in the meantime in favor of the Firefox UI Tests as run with Marionette.