1070669 - [mozlog] Make test_end track the status of its subtests

Status: NEW

(Testing :: Mozbase, defect)

Description

[Nick Alexander :nalexander [he/him]]

The test_start/test_end API is strange because test_status is optional.  For my harness, my results really come from test_status calls.  That means I need to track the current test, entering and exiting with start/end as necessary.  That's not so bad, but I need to track the running total of all my test_status calls and feed that into end.  That's awful!

This stuff is hierarchical; why not use Python to make it so?  You could actually provide a block based API:

with log.suite('suite') as s:
    with s.test('test') as t:
        t.status(..., 'OK')

This is an alternate approach to what I can now achieve with a (manually plumbed) StatusHandler.  I think it's better, because when my suite is done, I can use the reference to it, for example, to get all the status information that I'm going to use to return the right error code from my test runner.

My request: do my book-keeping for me!

Comment 1

[Nick Alexander :nalexander [he/him]]

Huh, typed that in and didn't make my points clearly:

1) track test_status results in the logger, so I don't have to do it myself (to provide to test_end).

2) ditto with overall suite results, so I don't have to add a StatusHandler directly.

3) consider a Pythonic API for hierarchical logging.

Comment 2

[James Graham [:jgraham]]

I don't think I understand the use case here, exactly.

The status in test_end is really supposed to be independent of the status in test_status entries. A status of "OK" doesn't indicate that all subtests passed, but that the test ran without experiencing a timeout or error. So it feels like if you are tracking each subtest result to set the overall test status you're doing something wrong.

I'm also not too sure what you want a custom status handler for. The ideal situation here is that all the results of your harnesses are set externally in mozharness / mach using a purely external tools that consume the logs. If you are writing a custom status handler for something that thing should either be part of the external tools, or, if it depends on internal information not exposed to the external tools, should be put into the logs somehow so that it is.

Comment 3

[Nick Alexander :nalexander [he/him]]

(In reply to James Graham [:jgraham] from comment #2)
> I don't think I understand the use case here, exactly.
> 
> The status in test_end is really supposed to be independent of the status in
> test_status entries. A status of "OK" doesn't indicate that all subtests
> passed, but that the test ran without experiencing a timeout or error. So it
> feels like if you are tracking each subtest result to set the overall test
> status you're doing something wrong.

Huh.  I find this counter-intuitive: I expect test status to depend on subtest status.  I think this is poorly communicated in the mozlog docs [1].  I read the section on test_start/end vs. test_status many times, and still got the wrong idea.  I think that's because test_status is optional, and that means that test_end means different things.  When there are test_status calls, it's what you describe: overall completion of the test.  When there are no test_status calls, test_end itself reflects the pass/fail status of the test.  That's confusing.

Maybe this ticket is to improve that API or documentation?

> I'm also not too sure what you want a custom status handler for. The ideal
> situation here is that all the results of your harnesses are set externally
> in mozharness / mach using a purely external tools that consume the logs. If
> you are writing a custom status handler for something that thing should
> either be part of the external tools, or, if it depends on internal
> information not exposed to the external tools, should be put into the logs
> somehow so that it is.

Sorry, I was unclear.  I spew a bunch of suite_*/test_* stuff to the logs, yes.  But I also need to spew aggregate pass/fail counts for mozharness to process (see [2]), and I need to return an error code from my test running script.  I'm doing that bookkeeping manually (possibly using StatusHandler, because it already exists.  And might, you know, track status).  Why do I need to do this manually, or plumb in a StatusHandler to do it for me?  The log object knows *everything that's happened*.  I want it to give me that data so I don't have to do this bookkeeping myself.

[1] http://mozbase.readthedocs.org/en/latest/mozlog_structured.html

[2] http://mxr.mozilla.org/build/source/mozharness/mozharness/mozilla/testing/errors.py

Comment 4

[Chris Manchester (limited bugmail, email directly)]

From discussion :nalexander, the priority here seems to be to improve the documentation of the current api in a way that clarifies its relationship with other models of test results. There may also be a valid use case we haven't covered for test harnesses interested in returning something non-zero on test failure. This could be addressed by installing a status handler by default and supplying its summary on demand.