Merge lp:~vila/autopilot/timestamped-subunit-stream into lp:autopilot

[Vincent Ladeuil]

Add timestamps to the subunit stream

This is a first step in fixing https://bugs.launchpad.net/ubuntu-sanity-tests/+bug/1408732.

The issue is that autopilot doesn't timestamp the tests in the stream to start with (so ubuntu-sanity-tests can't preserve them either).

Guidance welcome about where to add tests for that (I found autopilot/tests/unit/test_testresults.py but it doesn't seem to test the subunit stream specifically).

The fix can be checked by using 'subunit-ls --times ' on a subunit stream with and without that fix.

I tried running the autopilot test suite on my laptop but in 5 runs I got logged out 3 times from my session :-/

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:552
http://jenkins.qa.ubuntu.com/job/autopilot-ci/1044/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-amd64-ci/107
        deb: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-amd64-ci/107/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-armhf-ci/107
        deb: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-armhf-ci/107/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-i386-ci/111
        deb: http://jenkins.qa.ubuntu.com/job/autopilot-vivid-i386-ci/111/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-vivid-autopilot/159/console
    FAILURE: http://jenkins.qa.ubuntu.com/job/autopilot-testrunner-otto-vivid-autopilot/164/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-vivid-amd64/959
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-vivid-amd64/959/artifact/work/output/*zip*/output.zip

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/autopilot-ci/1044/rebuild

review: Needs Fixing (continuous-integration)

[Christopher Lee (veebers)]

Hi Vincent,

autopilot/tests/unit/test_testresults.py seems like a decent place to put the tests.

Regarding running the tests, which WM/DM are you running out of interest? It seems there may be an assumption the tests are making that is causing this to happen.

I ran some tests with trunk and this branch and compared the results of using 'subunit-ls --times'.

I saw similar results on both runs (the trunk version has some times) perhaps I'm missing something?

Also, I ran some functional tests (so they take a little longer per test) and found that when using this branch every result was 0.000 seconds (even though I was watching them run and they totally took longer than that) where the trunk run had times for each test. Perhaps I'm doing something wrong?

Commands I used:
  $ python3 -m autopilot.run run -v -o /tmp/subunit-output-vila.subunit -f subunit autopilot.tests.functional.test_input_stack

  $ subunit-ls --times /tmp/subunit-output-vila.subunit

The output along the lines of:
autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test_text_typing(UInput,lower_alpha) 0.000
autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test_text_typing(UInput,upper_alpha) 0.000
autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test_text_typing(UInput,numeric) 0.000
autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test_text_typing(UInput,punctuation) 0.000

review: Needs Information

[lp:~vila/autopilot/timestamped-subunit-stream]

553. By Vincent Ladeuil on 2015-04-15

Add a test to ensure we get a non-zero timestamp.

[Vincent Ladeuil (vila)]

...aaaaand I should have wrote the test first ;-)

> Hi Vincent,
>
> autopilot/tests/unit/test_testresults.py seems like a decent place to put the
> tests.

Ack, I went ahead and add one there indeed.

>
> Regarding running the tests, which WM/DM are you running out of interest?

unity7 on vivid (the default AFAIK).

> It
> seems there may be an assumption the tests are making that is causing this to
> happen.

Yeah, newcomer running into silly setup errors most probably ;)

Let's talk about it outside that MP may be ?

I will setup a kvm and re-run there instead.

>
> I ran some tests with trunk and this branch and compared the results of using
> 'subunit-ls --times'.
>
> I saw similar results on both runs (the trunk version has some times) perhaps
> I'm missing something?

I'm a bit confused myself that the test I added succeeds even without my patch... still digging ;)

>
> Also, I ran some functional tests (so they take a little longer per test) and
> found that when using this branch every result was 0.000 seconds (even though
> I was watching them run and they totally took longer than that) where the
> trunk run had times for each test. Perhaps I'm doing something wrong?

That one is puzzling...

class AutoTimingTestResultDecorator(HookedTestResultDecorator):
    """Decorate a TestResult to add time events to a test run.

    By default this will cause a time event before every test event,
    but if explicit time data is being provided by the test run, then
    this decorator will turn itself off to prevent causing confusion.
    """

I.e. timestamps should be added if none exist, you seem to observe that they are *removed* instead which makes litlle sense at that point ;)

>
> Commands I used:
> $ python3 -m autopilot.run run -v -o /tmp/subunit-output-vila.subunit -f
> subunit autopilot.tests.functional.test_input_stack
>
> $ subunit-ls --times /tmp/subunit-output-vila.subunit
>

Which is basically what my added test does.

> The output along the lines of:
> autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test
> _text_typing(UInput,lower_alpha) 0.000
> autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test
> _text_typing(UInput,upper_alpha) 0.000
> autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test
> _text_typing(UInput,numeric) 0.000
> autopilot.tests.functional.test_input_stack.InputStackKeyboardTypingTests.test
> _text_typing(UInput,punctuation) 0.000

Right, so the '0.000' is the issue.

Unfortunately I can't reproduce what you're seeing, I'm getting the opposite, but with failures, so I don't really trust that either ;-/

So, I'll restart from scratch, it seems I've missed something in my initial diagnosis...

Marking this MP 'in progress' until enlightenment ;)

Unmerged revisions

553. By Vincent Ladeuil on 2015-04-15

Add a test to ensure we get a non-zero timestamp.

552. By Vincent Ladeuil on 2015-04-14

Wrap the result object to get timestamps on subunit tests.

551. By Vincent Ladeuil on 2015-04-14

Ignore python3 caches.

=== modified file '.bzrignore'
--- .bzrignore	2013-12-10 01:26:22 +0000
+++ .bzrignore	2015-04-15 14:10:00 +0000
@@ -4,3 +4,4 @@
 .tox
 htmlcov
 .coverage
+**/__pycache__/

=== modified file 'autopilot/testresult.py'
--- autopilot/testresult.py	2015-01-27 00:10:54 +0000
+++ autopilot/testresult.py	2015-04-15 14:10:00 +0000
@@ -137,13 +137,12 @@
 
 def _construct_subunit(**kwargs):
     from subunit import StreamResultToBytes
+    from subunit import test_results
     stream = kwargs.pop('stream')
     failfast = kwargs.pop('failfast')
     _raise_on_unknown_kwargs(kwargs)
-    result_object = LoggedTestResultDecorator(
-        ExtendedToStreamDecorator(
-            StreamResultToBytes(stream)
-        )
-    )
+    result_object = test_results.AutoTimingTestResultDecorator(
+        LoggedTestResultDecorator(
+            ExtendedToStreamDecorator(StreamResultToBytes(stream))))
     result_object.failfast = failfast
     return result_object

=== modified file 'autopilot/tests/unit/test_testresults.py'
--- autopilot/tests/unit/test_testresults.py	2015-01-27 00:10:10 +0000
+++ autopilot/tests/unit/test_testresults.py	2015-04-15 14:10:00 +0000
@@ -20,7 +20,9 @@
 import codecs
 from unittest.mock import Mock, patch
 import os
+import subprocess
 import tempfile
+import time
 
 from fixtures import FakeLogger
 from testtools import TestCase, PlaceHolder
@@ -333,6 +335,40 @@
         self.assertEqual(1, test_result.testsRun)
 
 
+class TestSubunitResult(TestCase):
+    def setUp(self):
+        super().setUp()
+        self.output_path = tempfile.mktemp()
+        self.addCleanup(remove_if_exists, self.output_path)
+
+    def test_timestamp_for_tests(self):
+        # Ensure that the subunit stream embeds timestamps for each test
+        class MyTest(TestCase):
+            def test_pass(self):
+                # sleep enough to have some duration for the test
+                time.sleep(0.002)
+
+        t = MyTest('test_pass')
+        stream = run.get_output_stream('subunit', self.output_path)
+        result = testresult.get_output_formats()['subunit'](
+            stream=stream, failfast=False)
+        result.startTestRun()
+        t.run(result)
+        result.stopTestRun()
+        stream.flush()
+        # We just rely on subunit-ls to extract the test timestamps.  If none
+        # are included we'll get very short duration (0.000) representing the
+        # time it takes to parse the stream. Since there are is no
+        # details/artifacts here, making the test sleep should be enough to
+        # distinguish between a stream with or without timestamps.
+        ls_output = subprocess.check_output(
+                ['subunit-ls', '--times', self.output_path],
+                universal_newlines=True
+            ).strip()
+        test_name, duration = ls_output.split()
+        self.assertNotEqual('0.000', duration)
+
+
 def remove_if_exists(path):
     if os.path.exists(path):
         os.remove(path)