@valhallasw: Do you have any little idea why these tests are failing on Travis only after re-implementing a kind of your compat's cache_output? Most of them are your's rPWBC8b965bb. Unfortunately I am at a loss here.

Seems it is not related to rPWBCce36af1 because tests are failing on Appveyer too in Merge "[tests] Remove WindowsTerminalTests" [1]
but previous test passed "[tests] Fix page_tests after BasePage initializer was changed" [2] and I can't see that
rPWBCd327581 is related to this failing.

[1] https://ci.appveyor.com/project/Ladsgroup/pywikibot-g4xqx/build/job/al3j8cxsgx2kqyuo?fullLog=true
[2] https://ci.appveyor.com/project/Ladsgroup/pywikibot-g4xqx/builds/39183175/job/2we67x86g6byrj7p?fullLog=true

Ooof. That was a long time ago :-)

• The job seems to have an unrelated issue wrt generating a musicbrainz family file
• My hypothesis: ui_tests monkey-patches ui._print and ui._raw_input as 'lowest level' methods to capture the output. _print is only called when the stream is flushed which _may_ not happen until all the way at the end, when the process ends. (but it can happen if the lock is unlocked at the right time... so 'it depends')
  • Adding a tactical .flush() before trying to assert anything probably solves the issue?

In T282962#7090973, @valhallasw wrote:

Ooof. That was a long time ago :-)

• The job seems to have an unrelated issue wrt generating a musicbrainz family file
• My hypothesis: ui_tests monkey-patches ui._print and ui._raw_input as 'lowest level' methods to capture the output. _print is only called when the stream is flushed which _may_ not happen until all the way at the end, when the process ends. (but it can happen if the lock is unlocked at the right time... so 'it depends')
  • Adding a tactical .flush() before trying to assert anything probably solves the issue?

Thanks a lot for your ideas. I tried to reproduce it locally but it always succeded with both unittest and pytest. But flushing looks like a good idea to try it out.

Change 691943 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@tests] [test] Test for T282962

https://gerrit.wikimedia.org/r/691943

Change 691943 merged by jenkins-bot:

[pywikibot/core@tests] [test] Test flushing ui for T282962

https://gerrit.wikimedia.org/r/691943

Change 692109 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@tests] [test] Test flushing ui for T282962

https://gerrit.wikimedia.org/r/692109

Change 692109 merged by Xqt:

[pywikibot/core@tests] [test] Test flushing ui and redefining TerminalHandler for T282962

https://gerrit.wikimedia.org/r/692109

Change 692328 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] [bugfix] calling UI.cache_output must reflect the keyword arguments

https://gerrit.wikimedia.org/r/692328

The behaviour on Travis is really strange. I've setted up some print statements:

def output(self, text, toStdout=False, targetStream=None):
    """Forward text to cache and flush if output is not locked.

    All input methods locks the output to a stream but collect them
    in cache. They will be printed with next unlocked output call or
    at termination time.
    """
    print('>>> output:', text)
    self.cache_output(text, toStdout=toStdout, targetStream=targetStream)
    if not self.lock.locked():
        self.flush()
    print('<<< output:', text)

def flush(self):
    """Output cached text."""
    print('>>> flush:', self.cache.qsize())
    if self.cache.qsize() and self.cache.empty():
        print('######### SIZE is >0 but QUEUE is EMPTY #####')
    while not self.cache.empty():
        args, kwargs = self.cache.get_nowait()
        print('##>', args)
        self.stream_output(*args, **kwargs)
        print('##<')
    print('<<< flush:', self.cache.qsize())

def cache_output(self, *args, **kwargs):
    """Put text to cache."""
    print('>>> cache_output:', self.cache.qsize(), args)
    self.cache.put_nowait((args, kwargs))
    print('<<< cache_output:', self.cache.qsize(), args)

def stream_output(self, text, toStdout=False, targetStream=None):
    """
    Output text to a stream.
    """
    print('>>> stream_output:', text, file=sys.stdout, flush=True)
    ….
    print('<<< stream_output:', text)

And found output like this:

tests/ui_tests.py::TestTerminalOutput::test_output
>>> output: output
>>> cache_output: 0 ('output\n',)
<<< cache_output: 1 ('output\n',)
>>> flush: 1
##> ('output\n',)
##<
<<< flush: 0
<<< output: output

FAILED

That looks like stream_output is called but does nothing, not even print the first line which means it is replaced somehow.

Change 692352 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] [tests] Set expected_failure_if for ui_tests on Travis

https://gerrit.wikimedia.org/r/692352

Change 692352 merged by Xqt:

[pywikibot/core@master] [tests] Set expected_failure_if for ui_tests on Travis

https://gerrit.wikimedia.org/r/692352

Change 692328 abandoned by Xqt:

[pywikibot/core@master] [bugfix] calling UI.cache_output must reflect the keyword arguments

Reason:

https://gerrit.wikimedia.org/r/692328

Change 692716 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] [bugfix] Do not use cache_output

https://gerrit.wikimedia.org/r/692716

Hi Xqt. For what it's worth I have the ui_tests inconsistently fail locally (it seems to happen about 70% of the time).

The inconsistent nature of the failures will make this hard to troubleshoot so I'd like to wait for CR 678644 to get merged before digging in, in case it fixes this. Once that's merged I'd be happy to take a look.

Change 692716 merged by jenkins-bot:

[pywikibot/core@master] [bugfix] Flush stream in TerminalHandler.emit()

https://gerrit.wikimedia.org/r/692716

In T282962#7106369, @atagar wrote:

Hi Xqt. For what it's worth I have the ui_tests inconsistently fail locally (it seems to happen about 70% of the time).

This corresponds with travis tests. I never found this behavour on my local tests and have no glue how to solve it. Looks like it has to do with CPU usage.

The inconsistent nature of the failures will make this hard to troubleshoot so I'd like to wait for CR 678644 to get merged before digging in, in case it fixes this. Once that's merged I'd be happy to take a look.

would reluctantly introduce new dependencies currently but detaching you ui_tests part would be highly applicable I think.

btw. I don't think that there is a problem with the implementation itself (I haven't seen any yet except of T283488) but the way the implementation is tested.

Change 696497 had a related patch set uploaded (by Xqt; author: Xqt):

[pywikibot/core@master] [bugfix] postpone hte cached output implementation

https://gerrit.wikimedia.org/r/696497

Change 696497 merged by jenkins-bot:

[pywikibot/core@master] [bugfix] postpone hte cached output implementation

https://gerrit.wikimedia.org/r/696497