Merge lp://staging/~jameinel/subunit/omit-times-623654 into lp://staging/~subunit/subunit/trunk

Thanks for doing this John. I'm sorry it took us so long to get around to your patch. I like the approach of only including 'time:' statements that are relevant to the filtered output, but I think this patch gets it slightly wrong.

For example, given the events::

time: 2010-10-17 20:40:05.577960Z
test: foo
time: 2010-10-17 20:41:05.672960Z
success: foo
time: 2010-10-17 21:29:21.727029Z
test: canonical.testing.layers.ZopelessLayer:tearDown
tags: zope:layer
time: 2010-10-17 21:29:21.727397Z
skip: canonical.testing.layers.ZopelessLayer:tearDown [
tearDown not supported
]

where we are filtering out success and want to see skips. The output should be::

time: 2010-10-17 21:29:21.727029Z
test: canonical.testing.layers.ZopelessLayer:tearDown
time: 2010-10-17 21:29:21.727397Z
skip: canonical.testing.layers.ZopelessLayer:tearDown [ multipart
Content-Type: text/plain
reason
17
tearDown not supported
0
]

Where the output with this patch is::

time: 2010-10-17 20:40:05.577960Z
time: 2010-10-17 21:29:21.727397Z
test: canonical.testing.layers.ZopelessLayer:tearDown
skip: canonical.testing.layers.ZopelessLayer:tearDown [ multipart
Content-Type: text/plain
reason
17
tearDown not supported
0
]

The differences being that the output from this branch includes the first 'time:' statement ever, which is not relevant to the displayed events, and that it excludes the 'time:' statement from between 'test' and 'skip'. There may be a significant chunk of time between a test starting and a test getting its result, and I think we want to show that as long as we're showing time.

As a reminder, a 'time:' statement in a subunit stream means that all subsequent statements can be thought of as occurring at that time, one after the other until the next 'time:' statement.

On a simpler level:
 * there are two tests named test_timing_filtered_w_add_unexpected_success
 * stopTestRun is defined twice

I think keeping the first time is actually ok and quite interesting.
The rest I agree with.

On Tue, Oct 19, 2010 at 10:26 AM, Robert Collins
<email address hidden> wrote:
> I think keeping the first time is actually ok and quite interesting.
> The rest I agree with.

FWIW, the way the branch behaves now it keeps the first timestamp
after the last interesting event and the first timestamp before the
next interesting event. So....

<BEGINNING>
time: 1
time: N
test: event
error: event
time: N + A
time: N + A + B
test: event2
error: event2
time: N + A + B + C
<END>

jml

Right, thats clearly bong.
I'd like to see, I think:
time:
time:
test: event
time:
error: event
time:
time:
test: event2
time:
error: event2
time:

That is, collapse N>2 time: sequences in the first, last events.

On Fri, Oct 22, 2010 at 7:02 PM, Robert Collins
<email address hidden> wrote:
> Right, thats clearly bong.
> I'd like to see, I think:
> time:
> time:
> test: event
> time:
> error: event
> time:
> time:

I don't see at all what having two "time:" statements here would mean.
In subunit protocol terms it means exactly the same as having only the
second time statement.

jml

On Sat, Oct 23, 2010 at 3:11 PM, John Arbash Meinel
<email address hidden> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> On 10/23/2010 5:29 AM, Jonathan Lange wrote:
>> On Fri, Oct 22, 2010 at 7:02 PM, Robert Collins
>> <email address hidden> wrote:
>>> Right, thats clearly bong.
>>> I'd like to see, I think:
>>> time:
>>> time:
>>> test: event
>>> time:
>>> error: event
>>> time:
>>> time:
>>
>> I don't see at all what having two "time:" statements here would mean.
>> In subunit protocol terms it means exactly the same as having only the
>> second time statement.
>>
>> jml
>>
>
> Not entirely. I believe there are test runners that tell you how *long*
> an event took. (bzr selftest -v). In which case doesn't it subtract the
> known time from the next time it sees?
>

From the README:
"The time directive acts as a clock event - it sets the time for all future
events. The value should be a valid ISO8601 time."

time: A
test: X
time: B
success: X
time: C
time: D

Thus, the net effect of two consecutive time events is to set the time
for all future events to whatever value was provided with the second
time event. The first is ignored.

jml

On Sat, Oct 23, 2010 at 7:23 PM, John Arbash Meinel
<email address hidden> wrote:
...
>> From the README:
>> "The time directive acts as a clock event - it sets the time for all future
>> events. The value should be a valid ISO8601 time."
>>
>> time: A
>> test: X
>> time: B
>> success: X
>> time: C
>> time: D
>>
>> Thus, the net effect of two consecutive time events is to set the time
>> for all future events to whatever value was provided with the second
>> time event. The first is ignored.
>>
>
> If you were computing "how long did success: X" take, wouldn't you
> subtract C from B?
>

Why would I compute how long "success: X" took? If I wanted to know
the amount of time between the test X starting and it completing, I'd
calculate B - A.

Also, and perhaps I'm being too pedantic here, but unless the subunit
protocol is being used in a non-standard way, time C does not mean
"when success: X finished", it means "when the first event after
success: X happened".

jml

On Sun, Oct 24, 2010 at 11:58 AM, Jonathan Lange <email address hidden> wrote:
>>> Thus, the net effect of two consecutive time events is to set the time
>>> for all future events to whatever value was provided with the second
>>> time event. The first is ignored.

Yes, but we're altering the stream and stripping other things. While
its ignored we could use to use it.

>>
>> If you were computing "how long did success: X" take, wouldn't you
>> subtract C from B?
>>
>
> Why would I compute how long "success: X" took? If I wanted to know
> the amount of time between the test X starting and it completing, I'd
> calculate B - A.

Yes.

> Also, and perhaps I'm being too pedantic here, but unless the subunit
> protocol is being used in a non-standard way, time C does not mean
> "when success: X finished", it means "when the first event after
> success: X happened".

Thats right, it means 'first event after success: X', which for
figuring out stuff in slow test runners may (or may not) be
interesting.

-Rob

On Sun, Oct 24, 2010 at 5:52 PM, Robert Collins
<email address hidden> wrote:
...
>> Also, and perhaps I'm being too pedantic here, but unless the subunit
>> protocol is being used in a non-standard way, time C does not mean
>> "when success: X finished", it means "when the first event after
>> success: X happened".
>
> Thats right, it means 'first event after success: X', which for
> figuring out stuff in slow test runners may (or may not) be
> interesting.

As might the second or third. If you are interested in the first event
after success: X, include it in the filter.

jml

I've been working on this branch, trying to make the tests a bit clearer and making sure that the behaviour is "correct" as Rob determines it (although I still hold to my point that two consecutive time: statements are meaningless).

Anyway, I came across bug 716554, which means that my comment dated 2010-10-19 isn't entirely appropriate -- this branch just keeps up an existing bug.

Personally, I would rather fix the bug first, then land this branch (or my version with clearer tests, lp:~jml/subunit/omit-times-623654). I don't think the order matters too much though.

That branch is up for review: https://code.launchpad.net/~jml/subunit/unmangle-time-716554/+merge/49439

Will definitely conflict with this.

http://bazaar.launchpad.net/~subunit/subunit/trunk/revision/141 has landed that branch and fixes the bug.