Trial should handle logged errors using an observer.

[jml]

source:branches/loggedErrors-1409 does this sort of. I'm still hazy on the behaviour we want.

• calls to log.err should fail the trial test in which they occur
• provide an assertLogs(x, f, *a, **kw) method that allows users to run a method and assert that it fails by calling log.err. I don't know what x should be.

The current behaviour has Trial storing all errors in variable in the log module and clearing that variable after every test is run. If there are any errors in the variable, Trial will fail the test during cleanup.

[exarkun]

The first bullet point sounds correct to me.

As for the second... I don't think assertLogs satisifies the same use-case as log.flushErrors(). The main case I can think of that it doesn't cover is the case where f returns a Deferred. Whatever replaces log.flushErrors() should handle this.

[jml]

[21:00] <exarkun> jml: The logged errors thing should work like this [21:01] <exarkun> jml: Tests should be able to decide on their own what it means when log events happen [21:01] <exarkun> jml: I like the current behavior as the default, but you should be able to turn it off [21:02] <exarkun> jml: TestCase or test methods themselves should be able to declare a callable as the log observer for themselves, and that can override the d [21:02] <jml> current behaviour == flushErrors and all? [21:02] <exarkun> nah [21:02] <exarkun> just the bit where if there are errors, the test fails [21:03] *** wsanchez has quit IRC () (n=wsanchez@…) [21:03] <exarkun> flushErrors should be deprecated [21:03] *** seb- has left #twisted (n=seberino@…) [21:03] <exarkun> t.p.log.flushErrors, that is [21:03] <exarkun> eh I was gonna say something about a new version appearing somewhere, but screw that [21:03] <exarkun> So yea, all the error capturing stuff goes away [21:04] <exarkun> if you want to catch errors, you do something like 'testFoo.failOnloggedErrors = False' and add your own log observer [21:04] <exarkun> possibly with some help from convenience methods from trial, but they're just convenience methods, they're nothing tightly tied to trial [21:04] *** Crast has joined #twisted (n=james@pdpc/supporter/active/crast) [21:06] <spiv> exarkun: @ignoreLoggedErrors ;) [21:06] <exarkun> @punchesInTheFace [21:07] <exarkun> crud this font sucks I can't do any exciting unicode garbage [21:07] *** exarkun switches back to freemono [21:07] <jml> exarkun: I think rather than having an attribute *and* adding your own log observer, you should just add your own log observer [21:08] <jml> exarkun: ok. I can smoke what you're rolling here. [21:08] <jml> exarkun: what about backwards compatibility? [21:08] <exarkun> jml: Just adding your own would be cool, but I dunno how trial would notice that and not do its own thing. [21:08] <exarkun> flushErrors and friends are deprecated for a while, then removed. [21:09] <exarkun> maybe there's a nicer thing we can do, but I can't think of it right now [21:09] <jml> exarkun: trial could call TestCase.observerFactory() for each test. [21:10] <jml> with a default implementation of an observer that adds all logged errors to the TestResult [21:10] <jml> (btw, Jimi Hendrix is much cooler when you have good headphones) [21:11] <exarkun> That would make it tough to have different observer behavior for different tests on the same TestCase [21:11] *** ousado_ has joined #twisted (n=johnny@…) [21:11] <exarkun> which I think is a use-case I care about [21:11] <exarkun> Hm [21:11] <exarkun> wait [21:11] *** ousado has quit IRC (Read error: 110 (Connection timed out)) (n=johnny@…) [21:11] <jml> how does this look?  http://www.rafb.net/paste/results/BD07Yf63.html [21:12] *** Zenethian has quit IRC (Remote closed the connection) (i=zen@…) [21:12] <jml> exarkun: not that tough.. there's an attribute with the name of the running test. I guess I could make that public.

[jml]

[21:00] <exarkun> jml: The logged errors thing should work like this
[21:01] <exarkun> jml: Tests should be able to decide on their own what it means when log events happen
[21:01] <exarkun> jml: I like the current behavior as the default, but you should be able to turn it off
[21:02] <exarkun> jml: TestCase or test methods themselves should be able to declare a callable as the log observer for themselves, and that can override the d
[21:02] <jml> current behaviour == flushErrors and all?
[21:02] <exarkun> nah
[21:02] <exarkun> just the bit where if there are errors, the test fails
[21:03] *** wsanchez has quit IRC () (n=wsanchez@A17-221-42-43.apple.com)
[21:03] <exarkun> flushErrors should be deprecated
[21:03] *** seb- has left #twisted (n=seberino@netblock-72-25-103-52.dslextreme.com)
[21:03] <exarkun> t.p.log.flushErrors, that is
[21:03] <exarkun> eh I was gonna say something about a new version appearing somewhere, but screw that
[21:03] <exarkun> So yea, all the error capturing stuff goes away
[21:04] <exarkun> if you want to catch errors, you do something like 'testFoo.failOnloggedErrors = False' and add your own log observer
[21:04] <exarkun> possibly with some help from convenience methods from trial, but they're just convenience methods, they're nothing tightly tied to trial
[21:04] *** Crast has joined #twisted (n=james@pdpc/supporter/active/crast)
[21:06] <spiv> exarkun: @ignoreLoggedErrors ;)
[21:06] <exarkun> @punchesInTheFace
[21:07] <exarkun> crud this font sucks I can't do any exciting unicode garbage
[21:07] *** exarkun switches back to freemono
[21:07] <jml> exarkun: I think rather than having an attribute *and* adding your own log observer, you should just add your own log observer
[21:08] <jml> exarkun: ok. I can smoke what you're rolling here.
[21:08] <jml> exarkun: what about backwards compatibility?
[21:08] <exarkun> jml: Just adding your own would be cool, but I dunno how trial would notice that and not do its own thing.
[21:08] <exarkun> flushErrors and friends are deprecated for a while, then removed.
[21:09] <exarkun> maybe there's a nicer thing we can do, but I can't think of it right now
[21:09] <jml> exarkun: trial could call TestCase.observerFactory() for each test.
[21:10] <jml> with a default implementation of an observer that adds all logged errors to the TestResult
[21:10] <jml> (btw, Jimi Hendrix is much cooler when you have good headphones)
[21:11] <exarkun> That would make it tough to have different observer behavior for different tests on the same TestCase
[21:11] *** ousado_ has joined #twisted (n=johnny@p548E94F1.dip0.t-ipconnect.de)
[21:11] <exarkun> which I think is a use-case I care about
[21:11] <exarkun> Hm
[21:11] <exarkun> wait
[21:11] *** ousado has quit IRC (Read error: 110 (Connection timed out)) (n=johnny@p548EA3C2.dip0.t-ipconnect.de)
[21:11] <jml> how does this look? http://www.rafb.net/paste/results/BD07Yf63.html
[21:12] *** Zenethian has quit IRC (Remote closed the connection) (i=zen@king.of.tehintarweb.info)
[21:12] <jml> exarkun: not that tough.. there's an attribute with the name of the running test. I guess I could make that public.

ungh

[jml]

Merged forward to branches:loggedErrors-1409-3

The bare minimum:

• By default, errors logged in a test should cause errors to be reported for that test.
• Errors that are logged during the suite run but outside of any particular test should be reported.
• Test authors should be able to suppress the default behaviour

Not sure about this:

• By default, errors logged in a test that is run inside another test should not cause the outer test to fail.

Also not sure what test authors should be able to do wrt trial and logged errors, apart from suppressing default behaviour. Remember that tests do not have access to the result object, so they can't (easily) define a custom observer that logs some errors.

Also not sure what the behaviour of flushErrors and ignoreErrors should be during the period of deprecation. Presumably Trial will simply ingore any "kept" errors.

[jml]

So, I've opted for a fairly straightforward mapping of the current behaviour. Up for review in loggedErrors-1409-3

[exarkun]

• test_log.py - mostly looks good, however:
  • needs a copyright header and a docstring
  • Mask is slightly subtle - please give it a docstring as well.
  • Is it necessary to raise RuntimeError in _makeRuntimeFailure? Failure(RuntimeError("test error")) should work just as well, unless it is important to have the traceback.
• unittest.py
  • _deprecatedFlushErrors is kind of scary - what if flushErrors has already been imported by the time it is hooked? I can't quite tell if this is possible, given that trial does get a chance to run before any other code, but it looks like _installObserver isn't installed until a test is about to be run, which is after that test's defining module has been imported. This might be alleviated by putting the guts of flushErrors into a separate function, having flushErrors delegate to it, and hooking the separate function instead.
  • The expression assigned to self._errors in _LogObserver.flushErrors is potentially very expensive due to its complexity. The windows slaves frequently log a large number of errors, and this will probably noticably slow them down. An explicit for loop with two conditional appends will work as well and be much more efficient.
  • Add a docstring for flushLoggedErrors

Good test coverage and docstrings, overall. There are some problems with the full Twisted test suite in this branch that need to be address, though. The compatibility with the old flushErrors does not seem to be complete. For example:

[ERROR]: twisted.test.test_pbfailure.PBFailureTestUnsafe.testNoSuchFailure

Traceback (most recent call last):
  File "/home/exarkun/Projects/Twisted/trunk/twisted/test/test_pbfailure.py", line 128, in gotFailure
    self.assertEquals(len(log.flushErrors(exc)), 1)
exceptions.TypeError: len() of unsized object

Many tests fail in this way for me. Some tests outside of the Twisted suite also fail with this change, seemingly because the way in which they are flushing errors no longer works properly. There also seems to be some inter-test crossover with unflushed logged errors, since many of the tests fail due to as many as 10 logged errors which they themselves did not log.

Re-assign when the Twisted suite passes. If you want to try it, the other suite I ran was Divmod's, but I can run it in the next review if you'd prefer.

[jml]

"""There also seems to be some inter-test crossover with unflushed logged errors, since many of the tests fail due to as many as 10 logged errors which they themselves did not log."""

There's little that can be done about that.

I've fixed all the point raised in bullet.

[exarkun]

Replying to jml:

"""There also seems to be some inter-test crossover with unflushed logged errors, since many of the tests fail due to as many as 10 logged errors which they themselves did not log.""" There's little that can be done about that. I've fixed all the point raised in bullet.

[exarkun]

Uh, crud. Accidentally edited the description.

These tests call flushErrors, so they should pass. Otherwise, why even bother with the pretense of compatibility in this branch?

Also one more thing I noticed, the deprecation warnings need to have the name of the function which is deprecated.

[jml]

I've added function names to the deprecation warnings and I've fixed a bug where logged errors weren't being flushed after being reported.

I tried running the vertex tests. For me, they break with both trunk and this branch. This branch introduces more errors (for one of the tests in test_q2q -- can't remember which), but I think that's because this branch reports every logged error. Trunk only reports just the first one.

Re-assigning for review.

[exarkun]

test_reporter.py and unittest.py conflict when merging to trunk.

[jml]

Rebranched to loggedErrors-1409-4

[exarkun]

test_log.py still needs a copyright header. Otherwise, looks good.

[jml]

(In [18352]) Use a log observer to catch and report errors logged during tests.

• Author: jml
• Reviewer: exarkun
• Fixes #1409

Deprecates log.flushErrors, log.ignoreErrors, log.clearIgnores and log.startKeepingErrors. It is believed that these were all added to support catching logged errors for trial.

Instead, we implement these with an observer, and provide TestCase.flushLoggedErrors as a replacement for log.flushErrors.