testing/mozbase/mozlog/tests/test_formatters.py
author Nikki S <nikkisharpley@gmail.com>
Fri, 24 May 2019 13:30:13 +0000
changeset 475373 ecf05645d8eb8d436dc908edd19403b790282084
parent 456436 5cf0c9b4e97bb208a2eaa3fdb3ad641b3b224b7a
child 476058 43d9e99a44c1cbe180433fc7eb7495af05cbe7c5
permissions -rw-r--r--
Bug 1552914 - [mozlog] Update formatters to reflect new known_intermittent field. r=jgraham The in-tree log formatters have been updated to reflect the new `known_intermittent` field, ensuring that a status matching a `known_intermittent` status is not logged as an unexpected failure. A message is printed when there is a test status that matches this. A test for known intermittents has been added to the test_formatters, following the same testing style for pass or fail. Differential Revision: https://phabricator.services.mozilla.com/D32174

# This Source Code Form is subject to the terms of the Mozilla Public
# License, v. 2.0. If a copy of the MPL was not distributed with this
# file, You can obtain one at http://mozilla.org/MPL/2.0/.

from __future__ import absolute_import, print_function, unicode_literals

import mozunit
import pytest
from six import BytesIO

from mozlog.structuredlog import StructuredLogger
from mozlog.formatters import (
    MachFormatter,
)
from mozlog.handlers import StreamHandler

formatters = {
    'mach': MachFormatter,
}

FORMATS = {
    # A list of tuples consisting of (name, options, expected string).
    'PASS': [
        ('mach', {}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: OK
 0:00.00 TEST_START: test_bar
 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 4 checks (1 subtests, 3 tests)
Expected results: 4
Unexpected results: 0
OK
""".lstrip(b'\n')),
        ('mach', {'verbose': True}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: OK
 0:00.00 TEST_START: test_bar
 0:00.00 PASS a subtest
 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 4 checks (1 subtests, 3 tests)
Expected results: 4
Unexpected results: 0
OK
""".lstrip(b'\n')),
    ],

    'FAIL': [
        ('mach', {}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1
 0:00.00 TEST_START: test_bar
 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2
FAIL a subtest - expected 0 got 1
    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
    @caps/tests/mochitest/test_bug246699.html:53:1
TIMEOUT another subtest
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: PASS, expected FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 5 checks (2 subtests, 3 tests)
Expected results: 1
Unexpected results: 4
  test: 2 (1 fail, 1 pass)
  subtest: 2 (1 fail, 1 timeout)

Unexpected Results
------------------
test_foo
  FAIL test_foo - expected 0 got 1
test_bar
  FAIL a subtest - expected 0 got 1
    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
    @caps/tests/mochitest/test_bug246699.html:53:1
  TIMEOUT another subtest
test_baz
  UNEXPECTED-PASS test_baz
""".lstrip(b'\n')),
        ('mach', {'verbose': True}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: FAIL, expected PASS - expected 0 got 1
 0:00.00 TEST_START: test_bar
 0:00.00 FAIL a subtest - expected 0 got 1
    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
    @caps/tests/mochitest/test_bug246699.html:53:1
 0:00.00 TIMEOUT another subtest
 0:00.00 TEST_END: Test OK. Subtests passed 0/2. Unexpected 2
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: PASS, expected FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 5 checks (2 subtests, 3 tests)
Expected results: 1
Unexpected results: 4
  test: 2 (1 fail, 1 pass)
  subtest: 2 (1 fail, 1 timeout)

Unexpected Results
------------------
test_foo
  FAIL test_foo - expected 0 got 1
test_bar
  FAIL a subtest - expected 0 got 1
    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
    @caps/tests/mochitest/test_bug246699.html:53:1
  TIMEOUT another subtest
test_baz
  UNEXPECTED-PASS test_baz
""".lstrip(b'\n')),
    ],

    'KNOWN-INTERMITTENT': [
        ('mach', {}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: FAIL
KNOWN-INTERMITTENT-FAIL test_foo
 0:00.00 TEST_START: test_bar
 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
KNOWN-INTERMITTENT-PASS a subtest
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 4 checks (1 subtests, 3 tests)
Expected results: 4 (2 known intermittents)
Unexpected results: 0

Known Intermittent Results
--------------------------
test_foo
  KNOWN-INTERMITTENT-FAIL test_foo
test_bar
  KNOWN-INTERMITTENT-PASS a subtest
OK
""".lstrip(b'\n')),
        ('mach', {'verbose': True}, b"""
 0:00.00 SUITE_START: running 3 tests
 0:00.00 TEST_START: test_foo
 0:00.00 TEST_END: FAIL
KNOWN-INTERMITTENT-FAIL test_foo
 0:00.00 TEST_START: test_bar
 0:00.00 KNOWN-INTERMITTENT-PASS a subtest
 0:00.00 TEST_END: Test OK. Subtests passed 1/1. Unexpected 0
KNOWN-INTERMITTENT-PASS a subtest
 0:00.00 TEST_START: test_baz
 0:00.00 TEST_END: FAIL
 0:00.00 SUITE_END

suite 1
~~~~~~~
Ran 4 checks (1 subtests, 3 tests)
Expected results: 4 (2 known intermittents)
Unexpected results: 0

Known Intermittent Results
--------------------------
test_foo
  KNOWN-INTERMITTENT-FAIL test_foo
test_bar
  KNOWN-INTERMITTENT-PASS a subtest
OK
""".lstrip(b'\n')),
    ],
}


def ids(test):
    ids = []
    for value in FORMATS[test]:
        args = ", ".join(["{}={}".format(k, v) for k, v in value[1].items()])
        if args:
            args = "-{}".format(args)
        ids.append("{}{}".format(value[0], args))
    return ids


@pytest.fixture(autouse=True)
def timestamp(monkeypatch):

    def fake_time(*args, **kwargs):
        return 0

    monkeypatch.setattr(MachFormatter, '_time', fake_time)


@pytest.mark.parametrize("name,opts,expected", FORMATS['PASS'],
                         ids=ids('PASS'))
def test_pass(name, opts, expected):
    buf = BytesIO()
    fmt = formatters[name](**opts)
    logger = StructuredLogger('test_logger')
    logger.add_handler(StreamHandler(buf, fmt))

    logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
    logger.test_start('test_foo')
    logger.test_end('test_foo', 'OK')
    logger.test_start('test_bar')
    logger.test_status('test_bar', 'a subtest', 'PASS')
    logger.test_end('test_bar', 'OK')
    logger.test_start('test_baz')
    logger.test_end('test_baz', 'FAIL', 'FAIL', 'expected 0 got 1')
    logger.suite_end()

    result = buf.getvalue()
    print("Dumping result for copy/paste:")
    print(result)
    assert result == expected


@pytest.mark.parametrize("name,opts,expected", FORMATS['FAIL'],
                         ids=ids('FAIL'))
def test_fail(name, opts, expected):
    stack = """
    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
    @caps/tests/mochitest/test_bug246699.html:53:1
""".strip('\n')

    buf = BytesIO()
    fmt = formatters[name](**opts)
    logger = StructuredLogger('test_logger')
    logger.add_handler(StreamHandler(buf, fmt))

    logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
    logger.test_start('test_foo')
    logger.test_end('test_foo', 'FAIL', 'PASS', 'expected 0 got 1')
    logger.test_start('test_bar')
    logger.test_status('test_bar', 'a subtest', 'FAIL', 'PASS', 'expected 0 got 1', stack)
    logger.test_status('test_bar', 'another subtest', 'TIMEOUT')
    logger.test_end('test_bar', 'OK')
    logger.test_start('test_baz')
    logger.test_end('test_baz', 'PASS', 'FAIL')
    logger.suite_end()

    result = buf.getvalue()
    print("Dumping result for copy/paste:")
    print(result)
    assert result == expected

@pytest.mark.parametrize("name,opts,expected", FORMATS['KNOWN-INTERMITTENT'],
                         ids=ids('KNOWN-INTERMITTENT'))
def test_known_intermittent(name, opts, expected):
    buf = BytesIO()
    fmt = formatters[name](**opts)
    logger = StructuredLogger('test_logger')
    logger.add_handler(StreamHandler(buf, fmt))

    logger.suite_start(['test_foo', 'test_bar', 'test_baz'])
    logger.test_start('test_foo')
    logger.test_end('test_foo', 'FAIL', 'PASS', known_intermittent=['FAIL'])
    logger.test_start('test_bar')
    logger.test_status('test_bar', 'a subtest', 'PASS', 'FAIL',
                       known_intermittent=['PASS'])
    logger.test_end('test_bar', 'OK')
    logger.test_start('test_baz')
    logger.test_end('test_baz', 'FAIL', 'FAIL', 'expected 0 got 1',
                    known_intermittent=['PASS'])
    logger.suite_end()

    result = buf.getvalue()
    print("Dumping result for copy/paste:")
    print(result)
    assert result == expected


if __name__ == '__main__':
    mozunit.main()