unittest weirdness

[Ethan Furman]

So I finally got enough data and enough of an understanding to write some unit tests for my code.

These aren't the first unit tests I've written, but the behavior I'm getting is baffling.

I'm using 2.7.4 and I'm testing some routines which attempt to interpret data from a flat file and create a new flat
file for later programmatic consumption.

The weird behavior I'm getting:

- when a test fails, I get the E or F, but no summary at the end
(if the failure occurs in setUpClass before my tested routines
are actually called, I get the summary; if I run a test method
individually I get the summary)

- I have two classes, but only one is being exercised

- occasionally, one of my gvim windows is unceremoniously killed
(survived only by its swap file)

I'm running the tests under sudo as the routines expect to be run that way.

Anybody have any ideas?

--
~Ethan~

--snippet of code--

from VSS.path import Path
from unittest import TestCase, main as Run
import wfbrp

class Test_wfbrp_20140225(TestCase):

@classmethod
def setUpClass(cls):
cls.pp = wfbrp.PaymentProcessor(
'.../lockbox_file',
'.../aging_file',
[
Path('month_end_1'),
Path('month_end_2'),
Path('month_end_3'),
],
)

def test_xxx_1(self):
p = self.pp.lockbox_payments[0]
# affirm we have what we're expecting
self.assertEqual(
(p.payer, p.ck_num, p.credit),
('a customer', '010101', 10000),
)
self.assertEqual(p.invoices.keys(), ['XXXXXXXXXXX'])
self.assertEqual(p.invoices.values()[0].amount, 10000)
# now make sure we get back what we're expecting
np, b = self.pp._match_invoices(p)
missing = []
for inv_num in ('123456', '789012', '345678'):
if inv_num not in b:
missing.append(inv_num)
if missing:
raise ValueError('invoices %r missing from batch' % missing)

 

[John Gordon]

if missing:
raise ValueError('invoices %r missing from batch' % missing)

It's been a while since I wrote test cases, but I recall using the assert*
methods (assertEqual, assertTrue, etc.) instead of raising exceptions.
Perhaps that's the issue?

 

[Ethan Furman]

It's been a while since I wrote test cases, but I recall using the assert*
methods (assertEqual, assertTrue, etc.) instead of raising exceptions.
Perhaps that's the issue?

Drat. Tried it, same issue. O/S kills it.

 

[Terry Reedy]

It's been a while since I wrote test cases, but I recall using the assert*
methods (assertEqual, assertTrue, etc.) instead of raising exceptions.
Perhaps that's the issue?

Yes. I believe the methods all raise AssertionError on failure, and the
test methods are wrapped with try:.. except AssertionError as err:

if missing:
raise ValueError('invoices %r missing from batch' % missing)

should be "assertEqual(missing, [], 'invoices missing from batch')" and
if that fails, the non-empty list is printed along with the message.

 

[Ethan Furman]

It's been a while since I wrote test cases, but I recall using the assert*
methods (assertEqual, assertTrue, etc.) instead of raising exceptions.
Perhaps that's the issue?

Yes. I believe the methods all raise AssertionError on failure, and the test methods are wrapped with try:.. except
AssertionError as err:

if missing:
raise ValueError('invoices %r missing from batch' % missing)

should be "assertEqual(missing, [], 'invoices missing from batch')" and if that fails, the non-empty list is printed
along with the message.

I've tried it both ways, and both ways my process is being killed, presumably by the O/S.

I will say it's an extra motivating factor to have few failing tests -- if more than two of my tests fail, all I see are
'.'s, 'E's, and 'F's, with no clues as to which test failed nor why. Thank goodness for '-v' and being able to specify
which method of which class to run!

 

[Roy Smith]

I've tried it both ways, and both ways my process is being killed, presumably
by the O/S.

What evidence do you have the OS is killing the process?

Some systems have an oom (Out Of Memory) process killer, which nukes
(semi-random) process when the system exhausts memory. Is it possible
this is happening? If so, you should see some log message in one of
your system logs.

You didn't mention (or maybe I misssed it) which OS you're using. I'm
assuming you've got some kind of system call tracer (strace, truss,
dtrace, etc). Try running your tests under that. If something is
sending your process a kill signal, you'll see it:

[gazillions of lines elided]
write(1, ">>> ", 4>>> ) = 4
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
select(1, [0], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be
restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
+++ killed by SIGTERM +++

Alternatively, maybe something inside your process is just calling
sys.exit(), or even os._exit(). You'll see the exit() system call in
the strace output.

And, of course, the standard suggestion to reduce this down to the
minimum test case. You posted:

def test_xxx_1(self):
p = self.pp.lockbox_payments[0]
# affirm we have what we're expecting
self.assertEqual(
(p.payer, p.ck_num, p.credit),
('a customer', '010101', 10000),
)
self.assertEqual(p.invoices.keys(), ['XXXXXXXXXXX'])
self.assertEqual(p.invoices.values()[0].amount, 10000)
# now make sure we get back what we're expecting
np, b = self.pp._match_invoices(p)
missing = []
for inv_num in ('123456', '789012', '345678'):
if inv_num not in b:
missing.append(inv_num)
if missing:
raise ValueError('invoices %r missing from batch' % missing)

what happens if you reduce that to:

def test_xxx_1(self):
self.fail()

do you still get this strange behavior? What if you get rid of your
setUpClass()? Keep hacking away at the test suite until you get down to
a single line of code which, if run, exhibits the behavior, and if
commented out, does not. At that point, you'll have a clue what's
causing this. If you're lucky

 

[Ethan Furman]

What evidence do you have the OS is killing the process?

I put a bare try/except around the call to unittest.main, with a print statement in the except, and nothing ever prints.

Some systems have an oom (Out Of Memory) process killer, which nukes
(semi-random) process when the system exhausts memory. Is it possible
this is happening? If so, you should see some log message in one of
your system logs.

That would explain why my editor windows were being killed.

You didn't mention (or maybe I misssed it) which OS you're using.

Ubuntu 13 something or other.

I'm
assuming you've got some kind of system call tracer (strace, truss,
dtrace, etc).

Sadly, I have no experience with those programs yet, and until now didn't even know they existed.

Try running your tests under that. If something is
sending your process a kill signal, you'll see it:

[gazillions of lines elided]
write(1, ">>> ", 4>>> ) = 4
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
select(1, [0], NULL, NULL, NULL) = ? ERESTARTNOHAND (To be
restarted)
--- SIGTERM (Terminated) @ 0 (0) ---
+++ killed by SIGTERM +++

Alternatively, maybe something inside your process is just calling
sys.exit(), or even os._exit(). You'll see the exit() system call in
the strace output.

My bare try/except would have caught that.

And, of course, the standard suggestion to reduce this down to the
minimum test case. You posted:

def test_xxx_1(self):
p = self.pp.lockbox_payments[0]
# affirm we have what we're expecting
self.assertEqual(
(p.payer, p.ck_num, p.credit),
('a customer', '010101', 10000),
)
self.assertEqual(p.invoices.keys(), ['XXXXXXXXXXX'])
self.assertEqual(p.invoices.values()[0].amount, 10000)
# now make sure we get back what we're expecting
np, b = self.pp._match_invoices(p)
missing = []
for inv_num in ('123456', '789012', '345678'):
if inv_num not in b:
missing.append(inv_num)
if missing:
raise ValueError('invoices %r missing from batch' % missing)

what happens if you reduce that to:

def test_xxx_1(self):
self.fail()

I only get the strange behavior if more than two (or maybe three) of my test cases fail. Less than that magic number,
and everything works just fine. It doesn't matter which two or three, either.

do you still get this strange behavior? What if you get rid of your
setUpClass()? Keep hacking away at the test suite until you get down to
a single line of code which, if run, exhibits the behavior, and if
commented out, does not. At that point, you'll have a clue what's
causing this. If you're lucky

I strongly suspect it's memory. When I originally wrote the code I tried to include six months worth of EoM data, but
had to back it down to three as my process kept mysteriously dying at four or more months. There must be waaaaaaay too
much stuff being kept alive by the stack traces of the failed tests.

Thanks for your help!

 

[Roy Smith]

Alternatively, maybe something inside your process is just calling
sys.exit(), or even os._exit(). You'll see the exit() system call in
the strace output.

My bare try/except would have caught that.[/QUOTE]

A bare except would catch sys.exit(), but not os._exit(). Well, no
that's not actually true. Calling os._exit() will raise:

TypeError: _exit() takes exactly 1 argument (0 given)

but it won't catch os._exit(0)

I only get the strange behavior if more than two (or maybe three) of my test
cases fail. Less than that magic number,
and everything works just fine. It doesn't matter which two or three,
either.

OK, well, assuming this is a memory problem, what if you do:

def test_xxx_1(self):
l = []
while True:
l.append(0)

That should eventually run out of memory. Does that get you the same
behavior in a single test case? If so, that at least would be evidence
supporting the memory exhaustion theory.

I strongly suspect it's memory. When I originally wrote the code I tried to
include six months worth of EoM data, but
had to back it down to three as my process kept mysteriously dying at four or
more months. There must be waaaaaaay too
much stuff being kept alive by the stack traces of the failed tests.

One thing you might try is running your tests under nose
(http://nose.readthedocs.org/). Nose knows how to run unittest tests,
and one of the gazillion options it has is to run each test case in an
isolated process:

--process-restartworker
If set, will restart each worker process once their
tests are done, this helps control memory leaks from
killing the system. [NOSE_PROCESS_RESTARTWORKER]

that might be what you need.

 

[Steven D'Aprano]

There must
be waaaaaaay too much stuff being kept alive by the stack traces of the
failed tests.

I believe that unittest does keep stack traces alive until the process
ends. I thought that there was a recent bug report for it, but the only
one I can find was apparently fixed more than a decade ago:

http://bugs.python.org/issue451309

 

[Steven D'Aprano]

class Test_wfbrp_20140225(TestCase):

@classmethod
def setUpClass(cls):
cls.pp = wfbrp.PaymentProcessor(
'.../lockbox_file',
'.../aging_file',
[
Path('month_end_1'),
Path('month_end_2'),
Path('month_end_3'),
],
)

This has nothing to do with your actual problem, which appears to be the
Linux(?) OOM killer reaping your applications, just some general
observations on your test.

def test_xxx_1(self):

Having trouble thinking up descriptive names for the test? That's a sign
that the test might be doing too much. Each test should check one self-
contained thing. That may or may not be a single call to a unittest
assert* method, but it should be something you can describe in a few
words:

"it's a regression test for bug 23"
"test that the database isn't on fire"
"invoices should have a valid debtor"
"the foo report ought to report all the foos"
"...and nothing but the foos."

This hints -- its just a hint, mind you, since I lack all specific
knowledge of your application -- that the following "affirm" tests should
be pulled out into separate tests.

p = self.pp.lockbox_payments[0]
# affirm we have what we're expecting
self.assertEqual(
(p.payer, p.ck_num, p.credit),
('a customer', '010101', 10000),
)
self.assertEqual(p.invoices.keys(), ['XXXXXXXXXXX'])
self.assertEqual(p.invoices.values()[0].amount, 10000)

which would then leave this to be the Actual Thing Being Tested for this
test, which then becomes test_no_missing_invoices rather than test_xxx_1.

# now make sure we get back what we're expecting
np, b = self.pp._match_invoices(p)
missing = []
for inv_num in ('123456', '789012', '345678'):
if inv_num not in b:
missing.append(inv_num)
if missing:
raise ValueError('invoices %r missing from batch' %
missing)

Raising an exception directly inside the test function should only occur
if the test function is buggy. As Terry has already suggested, this
probably communicates your intention much better:

self.assertEqual(missing, [])

 

[Steven D'Aprano]

That would explain why my editor windows were being killed.

Try opening a second console tab and running top in it. It will show the
amount of memory being used. Then run the tests in the first, jump back
to top, and watch to see if memory use goes through the roof:

top -Mm -d 0.5

will sort by memory use, display memory in more sensible human-readable
units instead of bytes, and update the display every 0.5 second. You can
then hit the "i" key to toggle display of idle processes and only show
those that are actually doing something (which presumably will include
Python running the tests).

This at least will allow you to see whether or not memory is the concern.

 

[Ethan Furman]

top -Mm -d 0.5

Cool, thanks!

 

[Ethan Furman]

[snip lots of good advice for unit testing]

I was just removing the Personally Identifiable Information. Each test is pulling a payment from a batch of payments,
so the first couple asserts are simply making sure I have the payment I think I have, then I run the routine that is
supposed to match that payment with a bunch of invoices, and then I test to make sure I got back the invoices that I
have manually verified are the correct ones to be returned.

There are many different tests because there are many different paths through the code, depending on exactly which
combination of insanities the bank, the customer, and the company choose to inflict at that moment.

 

[Terry Reedy]

I strongly suspect it's memory. When I originally wrote the code I
tried to include six months worth of EoM data, but had to back it down
to three as my process kept mysteriously dying at four or more months.
There must be waaaaaaay too much stuff being kept alive by the stack
traces of the failed tests.

There is an issue or two about unittest not releasing memory. Also,
modules are not cleared from sys.modules, so anything accessible from
global scope is kept around.