Decouple Twisted logging inside AsynchronousDeferredRunTest

[jml]

This patch works towards fixes for https://pad.lv/942785 and https://pad.lv/1515362. I believe it makes no behavioral changes and introduces no new APIs.

On IRC, @rbtcollins suggest that AsynchronousDeferredRunTest was conflating responsibilities: taking over the Twisted logs in addition to being responsible for spinning the reactor and gathering errors.

This patch begins to untangle these responsibilities. It deprecates run_with_log_observers and ceases to use it. The functionality of run_with_log_observers is split into two Fixtures: _NoTwistedLogObservers (removes all log observers) and _TwistedLogObservers (adds some log observers).

It then provides two new specialized fixtures: _CaptureTwistedLogs (stores all Twisted logs as a detail) and _ErrorObserver (records all log.err calls—necessary for preserving expected behavior in Twisted tests). These fixtures are then used in AsynchronousDeferredRunTest to provide the same functionality that we provided before.

My intent is that a follow-up patch would add parameters to AsynchronousDeferredRunTest to disable the use of _NoTwistedLogObservers and _CaptureTwistedLogs, and perhaps also expose the two fixtures at the same time. This would allow users to work around lp:942785 and lp:1515362.

My big qualm about this patch is that it makes fixtures a dependency. Since testtools is a dependency of fixtures, this gives us a circular dependency. I think the "correct" fix is actually to move the entire deferredruntest option to a separate Python package (perhaps txtesttools), but even then, I don't know how we'd manage the deprecation smoothly. I welcome suggestions.

[rbtcollins]

I haven't reviewed yet, shall do today. However I don't believe the circular dependency is a problem: pure Python has no build-time requirements, all our source can be compiled. We can't test until all things are compiled, and for distros that conflate build-and-test this is a problem, but one which is describable in the Debian multi-stage mechanism they added to deal with genuine loops during bootstrapping archives.

[rbtcollins]

Review status: 0 of 5 files reviewed at latest revision, 4 unresolved discussions.

---

testtools/deferredruntest.py, line 103 [r1] (raw file): It would be safer to add this cleanup before calling _remove_observers. If _remove_observers is interrupted halfway through, no cleanups would run with the current code. Since _remove_observers itself isn't atomic, I'd actually not use it at all. Instead:

for observer in real_observers:
    publisher.removeObserver(observer)
    self.addCleanup(publisher.addObserver, observer)

Which should only lose observer if a signal based interrupt like KeyboardInterrupt is generated between those two lines of code.

---

testtools/deferredruntest.py, line 117 [r1] (raw file): And here too, naturally. Probably worth a single helper that takes publisher, observers, fixture

---

testtools/deferredruntest.py, line 129 [r1] (raw file): Since this is only relevant when the fixture is setUp, I would either not set it here, or set it to None.

---

testtools/deferredruntest.py, line 137 [r1] (raw file): This is very odd: its making multiple use of the fixture hard/buggy to use - since its propogating state across uses. What is it for?

---

Comments from the review on Reviewable.io

[jml]

Thanks for the review.

After reflecting over-night, I think even more that moving the Twisted code out of testtools into a separate package is the right thing to do. Even separately from the circular dependency issue, I think it's a clearer separation of responsibilities.

But maybe it's OK to land this as-is and see what happens.

---

Review status: 0 of 5 files reviewed at latest revision, 4 unresolved discussions.

---

testtools/deferredruntest.py, line 103 [r1] (raw file): Done.

---

testtools/deferredruntest.py, line 117 [r1] (raw file): Fixed. Not made the helper, since each one is reversed from the other, and the helper would be more complicated than code it helps.

---

testtools/deferredruntest.py, line 129 [r1] (raw file): Entire attribute gone now in response to comment below.

---

testtools/deferredruntest.py, line 137 [r1] (raw file): It's to capture errors logged while the fixture is active.

I've ditched logged_errors and this method entirely, in favour of _run_core calling flush_logged_errors directly, which I like much better.

---

Comments from the review on Reviewable.io

[jml]

We discovered https://clusterhq.atlassian.net/browse/FLOC-3681 while using this patch.

If we install _NoTwistedLogObservers as a fixture, and the test times out, we don't clean it up (see #897196). This means that tests that time out will fail with a weird error.

I've adjusted the code to use with for _NoTwistedLogObservers and a custom try/finally for _CaptureTwistedLogs.

---

Review status: 0 of 5 files reviewed at latest revision, 4 unresolved discussions.

---

Comments from the review on Reviewable.io

[rbtcollins]

Review status: 0 of 5 files reviewed at latest revision, 8 unresolved discussions.

---

requirements.txt, line 9 [r2] (raw file): This will need a minimum version on it. Looks like 1.3.0 ?

---

_testtools/deferredruntest.py, line 157 [r2] (raw file):_ logs.getvalue returns a string, not a list of strings; this is going to be a potential performance problem with big logs - I recommend lambda: [logs.getvalue()]

---

_testtools/deferredruntest.py, line 187 [r2] (raw file):_ I see you put up a PR for this; perhaps link to the PR? Or should we prioritise that ahead of this?

---

testtools/deferredruntest.py, line 386 [r2] (raw file): That suggests a bug in the cleanup handling logic - and I saw the bug you filed about this. Perhaps reference the bug # here for your future self?

---

Comments from the review on Reviewable.io

[jml]

Review status: 0 of 5 files reviewed at latest revision, 8 unresolved discussions.

---

_requirements.txt, line 9 [r2] (raw file):_ Done.

---

_testtools/deferredruntest.py, line 157 [r2] (raw file):_ Done.

---

_testtools/deferredruntest.py, line 187 [r2] (raw file):_ Done.

No need to prioritize that ahead of this. If https://github.com/testing-cabal/fixtures/pull/22 gets in, we can just delete this (it's private, no compat issues) and use it. Making something fit for the fixtures library is a different, higher standard than making something we can use here & now.

---

testtools/deferredruntest.py, line 386 [r2] (raw file): Added reference to https://bugs.launchpad.net/testtools/+bug/897196.

FWIW, I think the longer-term correct strategy is for RunTest to have its own separate, pluggable fixture.

---

Comments from the review on Reviewable.io

[jml]

Squashed to master: af8e294