Multiple instances of LoggerListener are causing an infinite loop due to duplicated handlers attached

RESOLVED FIXED

Status

Testing Graveyard
Mozmill
--
critical
RESOLVED FIXED
6 years ago
2 years ago

People

(Reporter: whimboo, Assigned: whimboo)

Tracking

unspecified
Dependency tree / graph
Bug Flags:
in-testsuite +

Details

(Whiteboard: [mozmill-2.0+])

Attachments

(3 attachments)

(Assignee)

Description

6 years ago
The LoggerListener class overwrites the default handlers for stdout and stderr:

        sys.stdout = self.StdOutLogger(self.logger)
        sys.stderr = self.StdErrLogger(self.logger)

This should be avoided because it will cause an infinite loop if multiple instances of LoggerListener are getting created.

To fix this bug we should wait for the fix on bug 761564. Beside that I will already try to find a better solution to not remove this feature completely. 

Carrying over the mozmill-2.0 blocking flag from bug 761564.
(Assignee)

Comment 1

6 years ago
Created attachment 662839 [details]
Example output (custom handlers)
(Assignee)

Comment 2

6 years ago
Created attachment 662840 [details]
Example output (default handlers)
(Assignee)

Comment 3

6 years ago
So the only difference we would have when getting rid of the custom handlers is that e.g. dump statements in Firefox are not routed through the INFO level:

< INFO | ***** iteration: 0
---
> ***** iteration: 0

Personally I wouldn't care about this detail. I would even see it as an improvement because you would see this output even if not using the INFO or DEBUG console level.

Parsers which rely on our output on stdout and stderr should probably always take the route via the log file. So they wont be affected by this change.

I will still try to find another option to keep it but if we all agree I'm happy to remove it.
(Assignee)

Comment 4

6 years ago
So the problem here is actually not overriding the stdout and stderr default handlers but attaching more than one console handler to the `mozmill` logger. 

Not sure yet how to best solve it. I will poke around with some ideas.
(Assignee)

Comment 5

6 years ago
Created attachment 662891 [details]
Patch v1 [checked-in]

Pointer to Github pull-request
(Assignee)

Comment 6

6 years ago
Comment on attachment 662891 [details]
Patch v1 [checked-in]

(In reply to Henrik Skupin (:whimboo) from comment #3)
> < INFO | ***** iteration: 0
> ---
> > ***** iteration: 0

As mentioned earlier I wouldn't care about this problem. So I would also favor to not replace the default handlers. If we want to have such things in the log the test would have to call the log() method and not dump().

Beside that I make use of unique loggers now. That ensures that each logger only get one handler assigned. With this method you will even be able to create multiple logger listeners at once:

    from cStringIO import StringIO
    stream = StringIO()

    logger1 = LoggerListener(console_level="INFO")
    logger2 = LoggerListener(console_level="DEBUG", console_stream=stream)

    m = mozmill.MozMill.create(handlers=(logger1, logger2))
    m.run(tests)
    m.finish()

    print stream.getvalue()

One of the new feature here is the console_stream parameter which let consumers specify where the stdout output should end-up. By default it will be stdout but as the example above shows, you can get store all the output in another stream and analyze it later.
Attachment #662891 - Attachment description: Pointer to Github pull request: https://github.com/mozilla/mozmill/pull/100/files → Patch v1
Attachment #662891 - Flags: review?(jhammel)
Attachment #662891 - Flags: feedback?(ctalbert)
(Assignee)

Comment 7

6 years ago
Jeff, if you are ok with re-ordering the parameters of the LoggerListener constructor I will do.
(Assignee)

Updated

6 years ago
Summary: Avoid replacing of default stdout/stderr handlers in LoggerListener class → Multiple instances of LoggerListener are causing an infinite loop due to duplicated handlers attached

Comment 8

6 years ago
Comment on attachment 662891 [details]
Patch v1 [checked-in]

this works for me
Attachment #662891 - Flags: review?(jhammel) → review+
(Assignee)

Comment 9

6 years ago
Jeff, can you please check comment 7? If that's applicable to you I kinda would like to bring those in a good order grouped by topic. If not we can let it be as is.

Comment 10

6 years ago
(In reply to Henrik Skupin (:whimboo) from comment #9)
> Jeff, can you please check comment 7? If that's applicable to you I kinda
> would like to bring those in a good order grouped by topic. If not we can
> let it be as is.

I'd have to see the ordering before I could comment one way or the other.  If its unrelated to the rest of the changes, it could also go in a separate bug.
(Assignee)

Comment 11

6 years ago
Well, it's that change:
https://github.com/mozilla/mozmill/pull/100/files#L0L22

Kwargs for the log file and the console are kinda separated.
(Assignee)

Comment 12

6 years ago
Comment on attachment 662891 [details]
Patch v1 [checked-in]

I have landed this patch on master to unblock my work on mozmill-automation:
https://github.com/mozilla/mozmill/commit/f53ca04e3ccf665045fc70ac7d690331469ce8ea

I will attach a follow-up patch for at least one automated test.
Attachment #662891 - Attachment description: Patch v1 → Patch v1 [checked-in]
(Assignee)

Updated

6 years ago
Flags: in-testsuite?
(Assignee)

Updated

6 years ago
Severity: normal → critical
(Assignee)

Comment 13

6 years ago
Test has been added with:
https://github.com/mozilla/mozmill/commit/4169f06687d0c8804cf410c883f63681ddf80bb9
Status: ASSIGNED → RESOLVED
Last Resolved: 6 years ago
Flags: in-testsuite? → in-testsuite+
Resolution: --- → FIXED
(Assignee)

Updated

6 years ago
Blocks: 698769

Updated

6 years ago
Attachment #662891 - Flags: feedback?(ctalbert) → feedback+
Product: Testing → Testing Graveyard
You need to log in before you can comment on or make changes to this bug.