861766 - Mutt python tests should not show test output in the middle of the testrun

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[Andrei Eftimie]

Running mutt python tests should not log a RESULTS block for js tests that are run as part of the python tests.

In particular this happens in the 
> testscreenshotpath.py
test.

This test invokes 
> test_dummy.js
which prints the RESULTS block right after it finishes.

This test appears to be run through the CLI (mozmill) class

Comment 1

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

This is related to the Mozmill logger. It should be stopped logging to the console. Some of our tests are doing that already. So it should be a copy and paste action. Good for a mentored bug.

The tests can be found at:
https://github.com/mozilla/mozmill/tree/master/mutt/mutt/tests/python

Comment 2

[Vlad Dolezal]

Hi, I'm new to contributing to Mozilla (and open source projects in general), and I'd like to take on this bug.

Henrik, if I understand your comment above correctly, you're saying that some of the other tests are already stopping the logger from logging to the console. Could you point me towards a specific one that already does that? I think I can take it from there.

Comment 3

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

Hi Vlad, thank you for your interest. If you need more information beside the question you asked please let me know or join us on IRC in #automation.

The test for the logger itself will not show any of the stdout/stderr output in the console:
https://github.com/mozilla/mozmill/blob/master/mutt/mutt/tests/python/test_loggerlistener.py

Comment 4

[Vlad Dolezal]

Attachment: Proposed bugfix for bug #861766

Comment 5

[Vlad Dolezal]

Hi Henrik,

it turns out the problem was with a different file, namely testprofilepath.py. It's the one that gets run just before testscreenshotpath.py in the mutt suite of tests, that's why it seemed at first like the unwanted console output is related to that.

I've attached my solution to the bug. Let me know what you think.

Comment 6

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

Comment on attachment 740710 [details] [diff] [review]
Proposed bugfix for bug #861766

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

Great patch Vlad! I like it. That's why you already get my r+. But would you mind to address the comment as given inline before the landing? That would make it clean across the tests. Also please adjust the commit message to the bug summary.

::: mutt/mutt/tests/python/testprofilepath.py
@@ +45,2 @@
>          # run mozmill on it
>          process = ProcessHandler(['mozmill',

When we call mozmill via the process handler here, would you mind to move the test under cli and update the tests.ini manifest files? All cli tests should be at the same location. Could you do the same change for the other test in the cli folder too?

Comment 7

[Vlad Dolezal]

Attachment: Proposed bugfix for bug #861766, version 2

Alright, I've added the changes you asked for. I've also renamed the output-catching function to dummy_output because I thought it fit in nicely with the rest of the test :-).

For some reason, the diff tool ('git show') doesn't understand that the moved and modified file is still the same file, although the rest of git seems to be quite aware of it. Hmm.

Comment 8

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

Comment on attachment 741280 [details] [diff] [review]
Proposed bugfix for bug #861766, version 2

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

At least on Linux I'm still seeing that tests still write out content to stdout:

.../tmp/tmpfBg0S1....FFFScreenshots saved in /tmp/tmpCIeTBg
Screenshots saved in /tmp/tmpCIeTBg

The first one might be from the profile test? Not sure where the screenshot ones are coming from. Would you mind to check that please?

Comment 9

[Vlad Dolezal]

I've pinpointed the other two files that make the same mistake. test_bug690154.py and testscreenshotpath.py.

I've run into a few issues, though. Firstly, testscreenshotpath.py uses the Mozmill object, and its Mozmill.finish() method uses a straight-up print statement, with no clean way for me to intercept it by passing an argument to the function call. Secondly, if we only had one or two files making this mistake, I wouldn't mind too badly making a dummy_output() function in each file. But with four files doing this (and maybe more in the future), I think we need a more general solution.

I'm thinking we could either use decorators to wrap functions that like to print output to the console. Or, more sensibly, make changes to mutt.py itself, so that none of the output from the tests gets passed to the console, only the output from the test harness itself. (I've googled around and found some fairly simple code for redirecting stdout, so that shouldn't be a problem.) What do you think?

Comment 10

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

(In reply to Vlad Dolezal from comment #9)
> I've run into a few issues, though. Firstly, testscreenshotpath.py uses the
> Mozmill object, and its Mozmill.finish() method uses a straight-up print
> statement, with no clean way for me to intercept it by passing an argument
> to the function call. Secondly, if we only had one or two files making this

Oh, good find! Indeed that is something we should not do and not call print but use the logger. Would you mind to file this as a new bug? Given that this is Mozmill core we shouldn't track it in this bug.

That means all issues we currently have with extra output is the result of the before mentioned code? If that's the case I'm happy to get the patch landed.

Comment 11

[Vlad Dolezal]

Attachment: Proposed bugfix for bug #861766, version 3

Hi Henrik,

Here's a different (and I'm pretty sure better) way to tackle this issue. It cleanly solves the problem by capturing stdout from the python test runs, without hiding any data we actually want visible. I also double-checked that running mutt in verbose mode (-v) still works correctly.

Assuming this is the route we want to take, I have a quick question about how to handle the couple of small desirable changes we found while working on this bug. Like moving one of the python tests into the cli folder, and fixing some deprecated calls to mozmill. Would it be better to throw those in together with this fix, to keep the commit history short, or put them in as a separate patch, to have each commit represent a different issue? My hunch is that the latter, but I wanted to ask you to be sure.

Comment 12

[Vlad Dolezal]

And I forgot to add, yes, I'll file the new bug.

Comment 13

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

Comment on attachment 743489 [details] [diff] [review]
Proposed bugfix for bug #861766, version 3

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

I would really avoid replacing the stdout and stderr output handlers with custom versions. We have had a really bad time with bug 792412 about it. So no, please keep the former version you had. Even it's a bit of duplication for tests handling the CLI version of Mozmill.

Comment 14

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

(In reply to Vlad Dolezal from comment #11)
> Assuming this is the route we want to take, I have a quick question about
> how to handle the couple of small desirable changes we found while working
> on this bug. Like moving one of the python tests into the cli folder, and
> fixing some deprecated calls to mozmill. Would it be better to throw those

Given that we have to touch this test anyway we can get it moved to it's new place. At the same time I would also fix the ProcessHandler calls which are marked as deprecated. If there is anything else it might be better suited for a new bug, yes.

Thanks for the update!

Comment 15

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

Hi Vlad. Would you have the time for an update of your latest patch given my review comments?

Comment 16

[Vlad Dolezal]

Hi Henrik. I had two very busy weeks, and then came down with a cold. Don't worry, I haven't forgotten about this bug - and as soon as my head stops feeling like it's stuffed full of cotton, I'll be right back on it.

Comment 17

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

Great. So yes, take care of yourself first. Nothing is pressing here. Thanks!

Comment 18

[Vlad Dolezal]

Hi Henrik.

Alright, I'll take your judgment for it that we should avoid messing with stdout redirection unless necessary.

One last stab at avoiding copy-and-pasting code several times. Can we define the handler function once (I'm thinking of calling it mutt_test_output_handler() ), and just import it in each of the tests that needs it? And if so, where would be the best spot to define it? Inside mutt itself, in another existing file, in a new file?

I'll wait for your judgement. Then I'll either write it up this way, or just do it the copy-and-paste way, and either way I'll get all the things we talked about fixed and the patch ready for inclusion.

Comment 19

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

(In reply to Vlad Dolezal from comment #18)
> One last stab at avoiding copy-and-pasting code several times. Can we define
> the handler function once (I'm thinking of calling it
> mutt_test_output_handler() ), and just import it in each of the tests that
> needs it? And if so, where would be the best spot to define it? Inside mutt
> itself, in another existing file, in a new file?

I don't think that such a method has to be defined somewhere else. It's just a 'pass' in its body, right? At least that's what I'm seeing when looking at the patch v2. Can we just make it a lambda function, so we don't have to declare it separately? I don't think we need the longish comment.

Comment 20

[Vlad Dolezal]

Attachment: Proposed bugfix for bug #861766, version 4

Alright, here's the patch. You were right, using a lambda function seems like the perfect solution. I knew why I was asking you for your opinion :-).

Now the only test that prints output in the middle of the test run is testscreenshotpath.py, which is related to the separate bug #873364. So as best as I can tell, this patch should be ready to get landed.

By the way, poking through the code in testscreenshotpath.py, I discovered an odd little thing. Namely, the following code (where 'm' is an instance of mozmill):

> m.run([dict(path=self.path)])
> results = m.finish()

Which looks perfectly fine, except m.run() itself already contains code to run m.finish(), and returns the result of that. So with the above code, m.finish() gets run twice, and the code could be simplified to:

> results = m.run([dict(path=self.path)])

I'm not sure if there's a good reason for the way it's coded now, or if it's worth changing. It just seemed like running the finish block of code twice might lead to unwanted results at some point down the line, so I thought I should mention it.

Comment 21

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

(In reply to Vlad Dolezal from comment #20)
> By the way, poking through the code in testscreenshotpath.py, I discovered
> an odd little thing. Namely, the following code (where 'm' is an instance of
> mozmill):
> 
> > m.run([dict(path=self.path)])
> > results = m.finish()
> 
> Which looks perfectly fine, except m.run() itself already contains code to
> run m.finish(), and returns the result of that. So with the above code,
> m.finish() gets run twice, and the code could be simplified to:
> 
> > results = m.run([dict(path=self.path)])
> 
> I'm not sure if there's a good reason for the way it's coded now, or if it's
> worth changing. It just seemed like running the finish block of code twice
> might lead to unwanted results at some point down the line, so I thought I
> should mention it.

The patch on bug 859746 brought this in, and didn't update the tests accordingly. I think we most likely did it the wrong way. At the moment I wonder if it was right to get this landed. Most likely I will reopen the bug now so we can figure out what the best option is.

Comment 22

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

Comment on attachment 751363 [details] [diff] [review]
Proposed bugfix for bug #861766, version 4

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

Overall this looks fantastic. Good work Vlad! There is just a little nit, which I will fix before I land the patch.

::: mutt/mutt/tests/python/test_bug690154.py
@@ +27,4 @@
>      def test_JSON_structure(self):
>          passes = 1
>          self.path = self.make_test()
> +        

nit: Those trailing white-spaces should be killed.

Comment 23

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

Thank you very much for your very first patch, Vlad! You can clap in your hands given that it got landed on master: https://github.com/mozilla/mozmill/commit/e552188a44cdc2ef33a39ec799de9bebdc4e72f1

If you are interested in other bugs to fix, please let me know on Bugzilla, via email, or join us on IRC in the #automation channel. Thanks again!