797715 - --console-level=[INFO|WARNING] shouldn't show failure stack

Status: RESOLVED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

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

The INFO and WARNING level should have lesser details about the failure. Right now we have the full stack included too, which pollutes the output a lot. I just wonder if we can remove the stack information for the INFO and WARNING level. Mostly it's enough to see the following details to know what's going on:

    "message": "'1' should equal '2'", 
    "lineNumber": 2, 
    "name": "test", 
    "fileName": "file:///Volumes/data/code/mozmill/test.js"

Jeff, what do you think?

Comment 1

[Rohit]

(In reply to Henrik Skupin (:whimboo) [away 12/21 - 01/01] from comment #0)
> The INFO and WARNING level should have lesser details about the failure.
> Right now we have the full stack included too, which pollutes the output a
> lot. I just wonder if we can remove the stack information for the INFO and
> WARNING level. Mostly it's enough to see the following details to know
> what's going on:
> 
>     "message": "'1' should equal '2'", 
>     "lineNumber": 2, 
>     "name": "test", 
>     "fileName": "file:///Volumes/data/code/mozmill/test.js"
> 
> Jeff, what do you think?

I would like to work on this bug. Where do i start?

Comment 2

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

Rohit, thanks for your interest in this bug and sorry that it has been taken a while to get back to you. But I was on vacation.

To get started you should grab your copy of the Mozmill code:
https://github.com/mozilla/mozmill

Get familiar in running Mozmill:
https://wiki.mozilla.org/Auto-tools/Projects/Mozmill/RepoSetup

All related code to the logger you can find here:
https://github.com/mozilla/mozmill/blob/master/mozmill/mozmill/logger.py

Feel free to ask if you still have questions or join us on IRC in the #automation or #mozmill channel.

Comment 3

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

Rohit, are you still interested in working on that bug? Please let me know. Thanks.

Comment 4

[Mike Hoye [:mhoye]]

Can you confirm that you're still working on this bug?

Comment 5

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

We haven't heard from Rohit in the last 3 months, so I assume he does not. Lets put it back into the pot.

Comment 6

[Seamus]

Attachment: diff of a potential fix for less logger information on INFO and WARNING levels

Hello. I know I sort of did this the wrong way around by working on the fix before asking to take it, but I wasn't sure how long it might take me.

Anyway, I believe this fixes the issue

Comment 7

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

Hi Seamus, thank you for taking the stab on getting this fixed. We appreciate that. I will mark you as assignee of the bug so everyone knows that you are working on this bug. I will review the patch as soon as possible - most likely today.

Comment 8

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

Comment on attachment 744271 [details] [diff] [review]
diff of a potential fix for less logger information on INFO and WARNING levels

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

In general the result looks perfect. But I would like to forward the review to Jeff who has more knowledge about logging.

::: mozmill/mozmill/logger.py
@@ +312,5 @@
>          return logging.Formatter.format(self, record)
> +
> +class StackFilter(logging.Filter):
> +    def filter(self, record):
> +        record.msg = re.sub(r'"stack".*"message"', '"message"', record.msg, flags=re.DOTALL)

I wonder if we should convert the string to a dictionary first, remove all unwanted entries, and convert it back into a string. With this regex we assume that the message always comes after the stack. If that would be not the case, we would remove nearly any information.

Comment 9

[Jeff Hammel]

Comment on attachment 744271 [details] [diff] [review]
diff of a potential fix for less logger information on INFO and WARNING levels

I really don't have much to offer here, as I'm not really up on the code so much anymore.
I don't think this will really work.  You have Henrik's point that the order it is printed out, ABICT, is not guaranteed.  Also, since .* will match anything (especially with re.DOTALL), "message" could appear in the message, at least hypothetically.

If these aren't concerns, then this is probably fine.

Comment 10

[Seamus]

Attachment: revised diff for less logger information on INFO and WARNING levels

Hello. So yeah, you're right about the regex probably being too greedy and possibly removing extra information.

It turns out I was doing things the wrong way around so instead I went back and edited the formatter class and added a second one for when pprinting isn't being used.

The other change also didn't do a good job at keeping console and file logging seperated (if --console-level=INFO and --file-level=ERROR, the record would be changed for both of them, instead of just the console output), I think I fixed that now

I'm pretty sure that the "stack" information is always two levels deep in the dictionary when converted from a string into a dict, but I could be wrong about that and this might need some more changing

Comment 11

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

Comment on attachment 747178 [details] [diff] [review]
revised diff for less logger information on INFO and WARNING levels

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

I have a couple of comments which I made inline. Please have a look at those and let me know what you think. In general I would like to see feedback from Jeff too, given that I don't have that much insight into logger code. That said I would like if we could stay somewhat on the path that we can easily replace our logging code with mozlog later.

::: mozmill/mozmill/logger.py
@@ +26,4 @@
>          self.format = format
>          self.debug = debug
>          self.mozmill = None
> +        removeStack = False

Please move this declaration into the if conditions where it is used. It's not necessary at this level.

@@ +57,3 @@
>          formatter = logging.Formatter(template)
>  
>          if console_level:

Actually I'm not sure what this check is for. Doesn't it always result in True given that it has a value of not None?

@@ +57,5 @@
>          formatter = logging.Formatter(template)
>  
>          if console_level:
> +            if console_level in ["WARNING", "INFO"]:
> +                removeStack = True

I would use a `reduce = console_level in ["WARNING", "INFO"]`

@@ +75,2 @@
>              handler = logging.FileHandler(log_file, 'w')
> +            if format == "pprint-color":

This is not necessary for the file logger, which can not log colored text to a file.

@@ +332,4 @@
>          return logging.Formatter.format(self, record)
> +
> +# Formatter to remove stack when not pprint-ing
> +class StackFormatter(logging.Formatter):

I think we should have a base formatter for our needs, which also ColoredFormatter is based on. So we wouldn't have to write all that code twice.

@@ +333,5 @@
> +
> +# Formatter to remove stack when not pprint-ing
> +class StackFormatter(logging.Formatter):
> +    def __init__(self, format=None, edit=False):
> +        self.edit = edit

I would call it 'reduce' which is about reducing the information of the message.

@@ +343,5 @@
> +                    string = message[1]
> +                    dictionary = json.loads(string)
> +                    for k1 in dictionary:
> +                        for k2 in dictionary[k1]:
> +                            if k2 == "stack":

I would prefer a recursive call here, so we are independent on the level.

Comment 12

[Jeff Hammel]

I agree with all of these points. I would caution not making the logger overly complicated to the extent actionable

Comment 13

[Seamus]

Attachment: Another revised diff for less logger information on INFO and WARNING levels

Hello again,

Made some more changes following Henrik's comments, so it looks a bit neater now.
In terms of making the code less complication/shorter, I think there are one or two parts that can be removed completely as far as I can see (specifically the StdOutLogger and StdErrLogger classes as well as the regex don't seem to be used anywhere)

Comment 14

[Seamus]

Comment on attachment 752999 [details] [diff] [review]
Another revised diff for less logger information on INFO and WARNING levels

Whoops, this should be
>-    def __init__(self, format=None, use_color=True):
>+    def __init__(self, format=None, use_color=True, use_reduce=False):
>         msg = self.formatter_msg(format, use_color)
>         logging.Formatter.__init__(self, msg)
>         self.use_color = use_color
>+        self.use_reduce = use_reduce

Comment 15

[Jeff Hammel]

Comment on attachment 752999 [details] [diff] [review]
Another revised diff for less logger information on INFO and WARNING levels

I don't have time to do any reviewing here right now.  I will go with :whimboo as his reviews are thorough.

Comment 16

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

Comment on attachment 752999 [details] [diff] [review]
Another revised diff for less logger information on INFO and WARNING levels

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

Hi Seamus. I'm sorry for that it has been taken so long for the review. But I was swamped with a lot of reviews recently. I hope it didn't put you down in working on this bug.

I personally like this approach way better as the solutions we have had before. There are still some things to discuss and to clarify, but I think we are on the right track now. Thanks for that update! Any specific feedback comments you can find below.

::: mozmill/mozmill/logger.py
@@ +56,5 @@
>          formatter = logging.Formatter(template)
>  
> +        reduce = console_level in ["WARNING", "INFO"]
> +        console = logging.StreamHandler(console_stream)
> +        color =  (format == "pprint-color")

Please kill the extra white-space after the equal sign.

@@ +57,5 @@
>  
> +        reduce = console_level in ["WARNING", "INFO"]
> +        console = logging.StreamHandler(console_stream)
> +        color =  (format == "pprint-color")
> +        formatter = ColorFormatter(template, use_reduce=reduce, use_color=color)

Try to keep the right order of keywords and use them as specified as parameters in the appropriate __init__ method.

@@ +68,2 @@
>              handler = logging.FileHandler(log_file, 'w')
> +            formatter = ColorFormatter(template, use_reduce=reduce, use_color=False)

Same here as above.

@@ +306,4 @@
>              levelname_color = self.COLOR_SEQ % fore_color + \
>                                levelname + self.RESET_SEQ
>              record.levelname = levelname_color
> +        if self.use_reduce:

Please add a blank line before to separate those blocks.

@@ +311,5 @@
> +                message = record.msg.split("|")
> +                string = message[1]
> +                dictionary = json.loads(string)
> +                dictionary = self.removeKey(dictionary, "stack")
> +                return message[0] + "| " + json.dumps(dictionary, indent=2)

Please do not call dump() with the indent option. Formatting if requested will happen somewhere else.

@@ +313,5 @@
> +                dictionary = json.loads(string)
> +                dictionary = self.removeKey(dictionary, "stack")
> +                return message[0] + "| " + json.dumps(dictionary, indent=2)
> +            except:
> +                pass

Shouldn't we return the original message here?

@@ +323,5 @@
> +                del dictionary[k]
> +                break
> +            if isinstance(v, dict):
> +                self.removeKey(v, key)
> +        return dictionary

I don't see that we recursively go through the whole dictionary here. To be flexible we cannot assume that the stack is always present at the top level.

Comment 17

[Seamus]

Attachment: Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Hi Henrik, that's no problem at all. I assumed that once I didn't get a reply you were just busy.

I fixed the cosmetic issues. The indent issue is a little tricky as the formatting actually takes place before the code I added is called. So I added another argument to the ColorFormatter. This is a little messy, but the only other way I can think of doing it is to try move the code in __call__ into the ColorFormatter class, but I'm not sure if that would work.

As for returning the original message, the pass will drop down to the return statement which will return the message. I also noticed that I was accidentally removing the levelname from the messages too, so I added it back in.

As far as I can see the recursive call should work? I think the break I had meant that it didn't go to the very bottom level. If you substitute "stack" with "lineNumber" for example, it removes all the entries throughout the dictionary in deeper levels, but I could be missing something.

Thanks,
Seamus

Comment 18

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

Comment on attachment 768491 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Thanks Seamus! I'm not sure if I will have the chance to review it today, and I will be out the next week. So lets see if Clint can take this review. If not, I will do it once I'm back.

Comment 19

[cmtalbert]

Comment on attachment 768491 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

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

One nit, otherwise I think this looks pretty good.  Let's see what Henrik says too.

Thanks a bunch for the patch!

::: mozmill/mozmill/logger.py
@@ +55,5 @@
>          self.logger.setLevel(logging.DEBUG)
>          formatter = logging.Formatter(template)
>  
> +        indent = format in ["pprint", "pprint-color"]
> +        reduce = console_level in ["WARNING", "INFO"]

this is not a very intuitive name for the variable. I'd call it "print_stack" or something like that so that it's clear what it is you're doing with that variable.  Then sending in print_stack=False to your argument list will just make lots of good sense.

Comment 20

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

Sounds good. Seamus, can you please make that remaining change? Then we should be able to get this landed. Thanks!

Comment 21

[Seamus]

Attachment: Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Hi, sorry for the delay. Made that change, thanks for all the feedback/help guys.

Comment 22

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

Comment on attachment 774271 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

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

Looks like you did the wrong replacement here Seamus. What I see is a change from 'indent' to 'print_stack', while it should be 'reduce' -> 'print_stack'.

Comment 23

[Seamus]

Attachment: Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Whoops, my mistake. I think I see what he wanted me to do now, I've changed use_reduce to dont_print_stack, so when it's set to true, the stack info won't be printed.

Comment 24

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

Comment on attachment 776369 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

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

Sorry for the delay, but I was on vacation. In general this looks great now, and with the nits fixed we could get it landed! Thanks for the update.

::: mozmill/mozmill/logger.py
@@ +66,3 @@
>  
>          if log_file:
> +            print_stack = file_level in ["WARNING", "INFO"]

Similar to my comment below you might want to change that line to ´not in´.

@@ +69,2 @@
>              handler = logging.FileHandler(log_file, 'w')
> +            formatter = ColorFormatter(template, use_color=color, dont_print_stack=print_stack, use_indent=indent)

Using parameters names with a negative meaning is not the best option cause those can cause a lot of confusion. Lets call it print_stack so that we have ´print_stack=print_stack´. As of now I don't see which value we actually get.

Comment 25

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

Seamus, it would be great if we can get this patch into mozmill 2.0. Sadly we do not have that much time anymore until its release. Would you have the time to update the patch accordingly to the latest review comment? Thanks!

Comment 26

[Seamus]

Attachment: Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Hello, sorry about the delay, here's the update.

Thanks, Seamus

Comment 27

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

Comment on attachment 794269 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

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

There is one thing you should revert. Otherwise it looks good now. Would you be able to update the fix soon? We want to release 2.0rc5 in the next hours, and I really would like to have this patch included. Thanks!

::: mozmill/mozmill/logger.py
@@ +294,4 @@
>              msg = msg.replace("$RESET", "").replace("$BOLD", "")
>          return msg
>  
> +    def __init__(self, use_color, print_stack, use_indent, format=None):

Please do not change the order of those parameters here. Also you should keep the naming. Personally ´color´ does not mean ´use_color´ for me. It would just be a specific color. Same applies to the other parameters which are Boolean values.

Comment 28

[Seamus]

Attachment: Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

Only saw this now, hope I'm not too late

Comment 29

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

Comment on attachment 795553 [details] [diff] [review]
Revision of patch to change logger.py to remove stack info for INFO and WARNING levels

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

Don't worry. You got it up in time! Thanks for your fast follow-up Seamus! I think that looks great now and I will land it in a bit.

Comment 30

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

Landed on master:
https://github.com/mozilla/mozmill/commit/75f8b1ce23c77b1f08af739f0029ac63db158e3d

Seamus, let me know if you have interests to continue to learn and help us. We can certainly find something for you. Otherwise look yourself: http://www.joshmatthews.net/bugsahoy/?automation=1. Thanks!