[Zope3-dev] Win32 Tests - Zope 3 - Not OK :-(

[Tres Seaver]

On Mon, 2003-03-10 at 12:06, Tim Peters wrote:
> [Jeremy Hylton]
> > CRITICAL:txn:Transaction failed during second phase of two-phase commmit
> > ...
> > What makes you think threads are involved?
> 
> A bad hasty guess, based on the "ok" at the bottom and the "Not OK" in the
> Subject line.
> 
> > ...
> > These tests aren't failing, but they are causing critical-level logging
> > messages to be generated.
> 
> OK, it's expected then.
> 
> > I don't know how to disable the logging during testing.  I think,
> > ideally, we could add an assertion to the unit test that a log message
> > is generated.
> 
> It appears that the test runner spews "Not OK" independent of what unittest
> believes; I'm focused on the "Not OK" in the Subject line here; I don't how
> that comes to be or where the test runner code lives, but it appears to
> trigger upon finding anything in stdout or stderr other than unittest's
> end-of-run summary.

That is probably in the shell scripting being done inside of the cron
jobs / "at" entries which check out, build, and test zope on various
platforms (Chris Withers has both Windows and Linux versions of this
script;  somebody else is doing the FreeBSD side).

As Jeremy says, the test here should be installing a "faux" logger, and
then verifying that the expected CRITICAL entry is generated. 
Successful unit tests are *never* supposed to produce output beyone the
"OK" at the end of the run, in order to avoid the GuruParsesTestOutput
anti-pattern.

For consulting work with Zope2, we are using a pattern like this to test
that expected logging occurs:

  - In the "real" module, make the logger in use overridable, via
    calling a "testing-only" hook::

    from zLOG import LOG, PROBLEM

    def _setLogger(new_logger):

        """ Override standard logger.

        o ONLY FOR TESTING PURPOSES!!!
        """
        global LOG
        old_value = LOG
        LOG = new_logger
        return old_value

  - In the "test" module, install and remove a dummy logger when
    running tests which produce log output::

    class TestWithLogging(unittest.TestCase):

        _old_logger = _logged = None

        def _prepLogger(self):

            from <module under test> \
                import _setLogger

            self._old_logger = _setLogger(self._fauxLog)

        def _restoreLogger(self):

            from <module under test> \
                import _setLogger

            if self._old_logger is not None:
                _setLogger(self._old_logger)

        def _fauxLog(self, subsystem, severity, summary, detail='',
                     error=None, reraise=None):

            if self._logged is None:
                self._logged = []

            self._logged.append({ 'subsystem' : subsystem
                                , 'severity' : severity
                                , 'summary' : summary
                                , 'detail' : detail
                                , 'error' : error
                                , 'reraise' : reraise
                                })

         def tearDown(self):
             self._restoreLogger()

  - Test case methods can examine the contents of 'self._logged'
    to verify that expected logging occured.

Tres.
-- 
===============================================================
Tres Seaver                                tseaver@zope.com
Zope Corporation      "Zope Dealers"       http://www.zope.com