Code happens

Victor (here, here) grabbed me on IRC yesterday for some testr help. He had a super frustrating bug in glance: about one in thirty unit test runs, a test would fail. He’d spent hours tracking it down and still couldn’t reliably reproduce it.

Part of that was due to the glance tests taking a few minutes to run, so each iteration was slow, but another part was a lack of familiarity with the test tooling we use in OpenStack which can give rich data to help analyse such things.

I helped him out – and this post is a step by step handbook of what I did so that I can point people at it 🙂

tl;dr

1. start by duplicating the environment
2. setup automation so you are only doing the interesting (or at least not time consuming) bits
3. bisect and bisect and bisect

Firstly, I pulled down exactly the same code he was working on:

cd glance; git review -d 250083

This let me try to reproduce the thing. However, my normal reproduction facility couldn’t be used because the glance testr configuration depended on invoking testr within lockutils-wrapper. I’m still working through the implications, but for the short term I moved that to be testr’s problem.

So now I could make a python 34 venv and run testr directly:

tox -epy34 --notest; . .tox/py34/bin/activate; testr run --parallel

This is pretty important – it lets me get under the setup.py wrapper that projects use and now I have more control over what is happening. Plus I’m not dealing with tox recreating the venv or anything like that.

It turned out that only the unit tests had been ported to Python3, so I needed to filter down to just those tests. And because I didn’t want to sit here watching it, I set testr off to find a reproduction example on its own:

testr run --parallel --until-failure tests.unit

This runs the same set of tests – whatever you’ve specified in the normal way – in parallel, in a loop. It specifically reschedules and starts new backends (processes that are actually executing test code) each time around, so its very close to just scripting it in shell around testr, with only minor differences (such as not re-querying all the tests each time, because testr knows the full set already).

After an hour or so I had toggled back to look at the terminal, and there was a lovely backtrace and information on the failure. It looks something like this:

running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-160} \
lockutils-wrapper \
${PYTHON:-python} -m subunit.run discover -t ./ ./glance/tests --load-list /tmp/tmpafpyzyd5
Ran 2 tests in 0.485s (+0.011s)
PASSED (id=1614)
running=OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_TEST_TIMEOUT=${OS_TEST_TIMEOUT:-160} \
lockutils-wrapper \
${PYTHON:-python} -m subunit.run discover -t ./ ./glance/tests --load-list /tmp/tmpafpyzyd5
Traceback (most recent call last):
...
glance.common.exception.NotFound: b'Image not found'
======================================================================
FAIL: glance.tests.unit.v1.test_api.TestGlanceAPI.test_upload_image_http_nonexistent_location_url
tags: worker-0
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/robertc/work/openstack/glance/glance/tests/unit/v1/test_api.py", line 1149, in test_upload_image_http_nonexistent_location_url
self.assertEqual(404, res.status_int)
File "/home/robertc/work/openstack/glance/.tox/py34/lib/python3.4/site-packages/testtools/testcase.py", line 350, in assertEqual
self.assertThat(observed, matcher, message)
File "/home/robertc/work/openstack/glance/.tox/py34/lib/python3.4/site-packages/testtools/testcase.py", line 435, in assertThat
raise mismatch_error
testtools.matchers._impl.MismatchError: 404 != 201
Ran 2 tests in 0.419s (-0.061s)
FAILED (id=1615, failures=1 (+1))

Except that the id was much lower, there were multiple concurrent processes being run on each iteration, and the number of tests run much higher – 506 in fact. The important bit to me was the id, because with that we could get programmatic on the problem.

While testr has support for automatically isolating faults, this depends on deterministic behaviour- there isn’t [yet] any support for things that fail 1 time in N when doing bisection, looking for cross-test interactions and so forth. So normally, one would just run:

testr run --analyze-isolation

And testr would churn away and give a useful answer, in this case I needed to do it by hand. I think there is room for getting really smart about dealing with this sort of situation, but the simplest method is to just repeat each test (a run of some X tests looking for a failure) until some confidence level is reached, rather than assuming a pass is actually a pass.

To do that we needed to do two things: we needed a set of tests to run, and a way to reduce the set and repeat. We could use –until-failure as a way to repeat a given test, and stop it after a couple of hours if it hadn’t failed.

Extracting the tests that a given backend ran is straightforward, if not something you’d just luck upon. If the run id you want to investigate is 6, and the backend that you want to report on is worker-0 (see the test tag in the error report above):

cat .testr/6 | subunit-1to2 | subunit-filter -s --xfail --with-tag=worker-0 | subunit-ls > worker-0

This takes the subunit stream from the repository, which is in a legacy format 1, upgrades it to subunit v2, then includes successful tests and expected failures, but only includes tests run on worker-0, pulls out the test ids (thats the subunit-ls bit) and writes it into a file ‘worker-0’.

To run just those tests:

testr run –load-list worker-0

More interestingly though, lets start by not running all the tests that took place after our failure. Inside the file it looks like this:

...
glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_deleted_image
glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_image_size_header_too_big
glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_public_image
glance.tests.unit.v1.test_api.TestGlanceAPI.test_upload_image_http_nonexistent_location_url
glance.tests.unit.v1.test_api.TestImageSerializer.test_meta
glance.tests.unit.v1.test_api.TestImageSerializer.test_show
...

Note that the test we’re interested in is in the middle there – though the file looks sorted, thats due to the test backend, what we have is the actual order tests executed in (and we don’t need to worry about concurrency because we pulled out just one backend process, and in Python unittest thats single-threaded).

First step then is to delete all the tests after the one we care about:

...glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_deleted_image
glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_image_size_header_too_big
glance.tests.unit.v1.test_api.TestGlanceAPI.test_update_public_image
glance.tests.unit.v1.test_api.TestGlanceAPI.test_upload_image_http_nonexistent_location_url

And then we don’t want to run all the tests: we’re assuming there is an interaction with a single other test leaving a stale process or something, so we want to run the one that failed, and half of the earlier tests; if they end up being reliable, we switch to the half we hadn’t been running, and then repeat the process – take half, run until we’re satisfied its reliable, repeat.

The way I do this by hand is to just edit the text file, making a new copy each step, so that I can backtrack easily. So delete half the preceeding lines, save to new file, then run:

testr run --load-list newfile --until-failure

Walk away, do something else, and then come back in a couple of hours.

This worked: from 506 tests on the worker, I then had about 300 that ran before the failing test after the first trim, so 150 was my first bisection which ran for a couple hours before failing. Then 75, then 35, then 18, then 9, then 5, then 2, then 1, then – 0 – thats right, eventually we found that the failing test could fail on its own!

And from that Victor was able to dig deep into what it was doing with confidence – he found a race condition in the test server setup stuff (I haven’t looked closely – I’m parroting what he said on IRC) – and is confident he’s found the bug. Yay!

I also ran one of the smaller sets overnight using Python 2.7, and that didn’t fail at all, so I suspect the failure is in some area that was masked by Python 2.7/eventlet on 2.7 handling of *something*. We saw a bug in subunit of that nature earlier this year, where a different (but legitimate) behaviour in eventlet on 3.4 led to subunit dropping writes silently. Thats fixed now in both eventlet and subunit 🙂

A test server acts as a little RPC server where we can ask it to run some tests without paying a full new-process startup cost each time. They are a necessary precondition to online scheduling of tests (because without them the latency of scheduling a test will be orders of magnitude more time than executing the test), as well as potentially enabling better debugger glue by providing an explicit out of band interface.

It’s vital that we don’t break existing users of subunit.run or testrepository when we bring this in – folk don’t react well to having their environment broken. Breaks could occur several different ways – but lets assume that an unmodified .testr.conf will not result in the server code being activated. (It would be nice in theory to Just Work and make things better, but there are lots of ways it could fail, starting with the fact that we have no negotiation step with the things we’re running, and anything else (e.g. exported environment variables) stands a high chance of being eaten by intermediaries like ssh, tox and so on).

So, assuming a new .testr.conf:

1. A newer subunit.run running with an old testrepository might drop into server mode and then not actually run any tests.
2. A newer testrepository with an older subunit.run might not go into server mode but not error cleanly.

Testr’s run command has two key interfaces with test backends. Firstly the list interface, where it queries for tests. This is only done when testr needs to know what tests exist (e.g. for offline scheduling). Secondly, the run interface where tests are executed.

In the server based world. testr will have one invoke-a-process interface, and that will offer the two existing interfaces over the basic RPC layer.

To avoid failure 1, we need to ensure we never ask for subunit.run to go into server mode except when testrepository itself can handle it. That implies that we must not insert whatever change we are making into the run_command in .testr.conf, and instead either use a variable substition, or a whole new command key to configure it. I’m in favour of a new command key, because it places less constraints on implementors of other languages.

To avoid failure 2, we need to be able to rigorously determine if a process has gone into server mode. E.g. the server has to send a handshake command of some sort.

Lets talk about failure modes that can occur once we have .testr.conf configured and new subunit.run and testrepository code.

3. We might have version skew between releases of subunit.run and testrepository on future updates to the RPC server.
4. We might have a broken testr -> server channel
5. We might have a broken server -> testr channel
6. The server might go off into a busy loop or something

For 3, we should version the RPC protocol carefully so that any semantic differences can be detected. Obviously there is a tonne of prior art and everyone is going to scream ‘use grpc’ (or fav RPC of choice). Thats a very sensible thing to do, and subunit can actually sit on top of pretty arbitrary transports as long as they can handle bytestrings and timestamps. That said, my focus in this iteration is to enable the server, porting subunit’s transport to something else won’t save time there (because the RPC angle is going to be a tiny fraction of the development time). I think a simple (new, old) version scheme will do fine (think autotools library soname calculations). If testr offered (5, 1) it means it can speak all versions between 1 and 5, and subunit.run as long as it speaks one of them, should pick that and use it. If we find the need to drop compatibility entirely with a version at some point, we raise the old to a version up from that and move on.

We can deal with 4 by pre-emptively sending a message from testr to the server – a hello message with the supported versions. Likewise, 5 can be dealt with by not considering the server ‘ok’ until we get its initial hello message with a chosen version.

If the server goes into a busy loop – I think we can largely ignore this for now, as its no different than today. (which is, the user notices, gets annoyed, and hits ctrl-C, or their CI job times out. Being able to discriminate between ‘the server is stuck’ and ‘a test is stuck’ would be good – and remembering that in a routed world we don’t know necessarily know the end point for any server…. it might just be routing.

What else – well one long running thing has been the desire to move away from requiring a clean stdin/stdout for test processes. Being broken when some test code decide to write to stdout is *not cool*. This new feature seems like an ideal time to address that. We can’t assume working networking (because e.g. tunnelling over ssh or a container console are important use cases). We could however write a little proxy that uses stdin/stdout with no test code, and then signals (however we’re doing that) that testr is listening on a local port, and tunnel it backwards. (If we choose something simple enough, it may even be possible to do that via parameterised ssh commands and no proxy at all). That does imply that testr itself still needs to be able to talk stdout/stdin. So – because testr has to keep doing that, I’m going to defer tackling this for now: it’s clearly scope creep and as such a dangerous temptation. Layer wise, it’s up to each server to decide how to be responsive when tests are cranky, and how to keep test output from compromising things. That does put the debugger integration work back (or at least, it leaves it as no better than the status quo) but its not in any way prejuidicial to it that I can tell.

Draft RPC spec

RPC packets will be stock subunit packets. Each packet will be for a test called ‘testrepository-rpc’ and contain a ‘application/json’ file attachment (with utf8 encoded text, per the default). The JSON message will be one of the messages defined below.

There are two endpoints, client (the initiator of the connection) and the server. Messages are not idempotent, and may be sent at any time from the client to the server. If a message requires a reply, the server may do so at any time, in any order. Subunit packets may be sent at any time from the client to the server, or the server to the client.

Overall lifecycle of a server:

1. Client sends a Hello message.
2. Server sends a Hello response.
3. Both ends pick the highest common version to define future messages.
4. Client sends commands, and server actions them.
5. Client sends a Goodbye message.
6. Server terminates itself.

Message definitions (version 1):

• Hello

  Advises the peer of the protocol versions supported.
  {“msg”: “Hello”, “max”: 1, “min”: 1}

• Goodbye

  Tells the server the client is finished and does not want to run any more tests. The server should cleanup and stop accepting messages. If the server was e.g. a trapdoor into a longer running process, it is undefined whether that longer running process should also terminate or not. No reply is permitted.
  {“msg”: “Goodbye”}

• List

  Tells the server to list some tests. A “Done” reply is required after all the tests have been listed. The output from the command should be subunit “exists” packets describing the tests that the server can run that were listed in the message. The tests property is optional – if absent, list all available tests.
  {“msg”: “List”, “tests”: [“testid”, …], “nonce”: “arbitrary string here”}

• Run

  Tells the server to run some tests. A “Done” reply is required after the tests have completed running. The output from the command should be a normal subunit stream resulting from running the tests specified. If the tests property is missing, run all available tests. Tests may be run in whatever order is most useful to the server.
  {“msg”: “List”, “tests”: [“testid”, …], “nonce”: “arbitrary string here”}

• Done

  Tells the client that some requested command has completed. The nonce must be the nonce for the message that this is in reply to.
  {“msg”: “Done”, “nonce”: “arbitrary string here”}

Implementation sketch

The RPC protocol needs to be accessible to anyone doing this in Python, client *and* server, so subunit seems like the sensible place to define the protocol. It will be pure code – no IO interactions – along with sufficient feature work in subunit’s API to make glueing it into e.g. testrepository and subunit.run straight forward.

In testr, we’ll look for a new command in .testr.conf, expressed much like the run command, and use that to determine that a server mode has been requested. If the server fails to start up, thats an error (e.g. it is up to users to get compatible code in place). When listing and running tests we’ll reuse the server except in isolation modes – both –isolated and –analyze-isolation – where reusing the server would violate the contract they have.

In subunit.run, we’ll add a command line flag to opt-in to the server. In the first implementation, the server is going to just be in-line in the call stack ; no threads or anything. So each command will just be an API call within the existing testtools/unitest2 API with a single subunit packet tacked on the end. We may need to do some ugly stuff to get out of the stock run framework – but I think it is doable.