databaseTest could collect all errors instead of reporting just the first

[rwest]

Motivation or Problem

It takes 8 minutes for me to run make test-database locally, and ~30 minutes on travis. When there are many mistakes to be fixed in the database, it's frustrating to have them listed one at a time and have to run the whole test suite again to reveal the next problem.

Desired Solution

Some of the tests (checking units, checking rates are reasonable) already collect up a list of failures and report them all. This is great. It'd be nice if all the other tests (nodes can be placed in trees, nodes are not duplicates, etc. etc.) did the same thing: log all the problems (with logging.error) and then fail the test at the end, rather than failing the test at the first problem.

[mjohnson541]

I've made a branch called databasetestimprove where I have a commit that I believe should enable this. So far I've confirmed that it passes tests on master. I haven't tested beyond that yet, but feel free to try it out.

[rwest]

That seems to do the trick (mostly).
I've pasted the output from the current RMG-cat database test below.
There are a some types of error that can still cause it to stop immediately, such as that first example AttributeError: 'NoneType' object has no attribute 'parent',
but the third example, ERROR: Kinetics family Surface_Abstraction: Entry is accessible? the error raised is raise ValueError("Error Occurred") and then it prints the captured logging with six separate errors -- very helpful. Thanks.

======================================================================
ERROR: Kinetics family Surface_Dissociation_vdW: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 992, in kinetics_checkSampleDescendsToGroup
    tst2.append((entry, [match]+family.groups.ancestors(match), """In group {0}, a sample molecule made from node {1} returns node {2} when descending the tree.
  File "/Users/rwest/Code/Cat/RMG-Py/rmgpy/data/base.py", line 849, in ancestors
    parent = node.parent
AttributeError: 'NoneType' object has no attribute 'parent'

======================================================================
ERROR: Kinetics family Surface_Dissociation: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Dissociation, a sample molecule made from node Combined returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *1 H u0 p0 c-1 {2,S} {3,S}
2 *2 H u0 p0 c0 {1,S}
3 *3 X u0 p0 c0 {1,S}


Origin Group AdjList:
1 *1 R  u0 {2,S} {3,[S,D,T]}
2 *2 R  u0 {1,S}
3 *3 Xo u0 {1,[S,D,T]}

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Kinetics family Surface_Abstraction: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Abstraction, a sample molecule made from node Abstracting returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *1 H u0 p0 c-1 {2,D}
2 *2 X u0 p0 c0 {1,D}


Origin Group AdjList:
1 *1 R  ux {2,[D,T,Q]}
2 *2 Xo u0 {1,[D,T,Q]}

root: ERROR: In family Surface_Abstraction, a sample molecule made from node Donating returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *3 H u0 p0 c-1 {2,S} {3,S}
2 *4 H u0 p0 c0 {1,S}
3 *5 X u0 p0 c0 {1,S}


Origin Group AdjList:
1 *3 R  ux {2,S} {3,[S,D,T]}
2 *4 R  ux {1,S}
3 *5 Xo u0 {1,[S,D,T]}

root: ERROR: In family Surface_Abstraction, a sample molecule made from node R-H returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *3 H u0 p0 c-1 {2,S} {3,S}
2 *4 H u0 p0 c0 {1,S}
3 *5 X u0 p0 c0 {1,S}


Origin Group AdjList:
1 *3 R  ux {2,S} {3,[S,D,T]}
2 *4 H  ux {1,S}
3 *5 Xo u0 {1,[S,D,T]}

root: ERROR: In family Surface_Abstraction, a sample molecule made from node R-O returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *4 O u0 p2 c0 {2,S} {3,S}
2 *3 H u0 p0 c-1 {1,S} {4,S}
3    H u0 p0 c0 {1,S}
4 *5 X u0 p0 c0 {2,S}


Origin Group AdjList:
1 *3 R  ux {2,S} {3,[S,D,T]}
2 *4 O  ux {1,S}
3 *5 Xo u0 {1,[S,D,T]}

root: ERROR: In family Surface_Abstraction, a sample molecule made from node R-OH returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *4 O u0 p2 c0 {2,S} {3,S}
2 *3 H u0 p0 c-1 {1,S} {4,S}
3    H u0 p0 c0 {1,S}
4 *5 X u0 p0 c0 {2,S}


Origin Group AdjList:
1 *4 O  ux {2,S} {4,S}
2 *3 R  ux {1,S} {3,[S,D,T]}
3 *5 Xo u0 {2,[S,D,T]}
4    H  u0 {1,S}

root: ERROR: In family Surface_Abstraction, a sample molecule made from node R-C returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *4 C u0 p0 c0 {2,S} {3,S} {4,S} {5,S}
2 *3 H u0 p0 c-1 {1,S} {6,S}
3    H u0 p0 c0 {1,S}
4    H u0 p0 c0 {1,S}
5    H u0 p0 c0 {1,S}
6 *5 X u0 p0 c0 {2,S}


Origin Group AdjList:
1 *3 R  ux {2,S} {3,[S,D,T]}
2 *4 C  ux {1,S}
3 *5 Xo u0 {1,[S,D,T]}

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Kinetics family Surface_Adsorption_Double: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Adsorption_Double, a sample molecule made from node Adsorbate returns an unexpectedly charged molecule:
Sample molecule AdjList:
multiplicity 3
1 *1 H u2 p0 c-1


Origin Group AdjList:
1 *1 R u2

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Kinetics family Surface_Bidentate_Dissociation: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Bidentate_Dissociation, a sample molecule made from node Combined returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *2 H u0 p0 c-2 {2,D} {3,S}
2 *1 H u0 p0 c-2 {1,D} {4,S}
3 *3 H u0 p0 c0 {1,S}
4 *4 X u0 p0 c0 {2,S}


Origin Group AdjList:
1 *1 R  u0 {2,[D,T]} {4,[S,D]}
2 *2 R  u0 {1,[D,T]} {3,S}
3 *3 R  u0 {2,S}
4 *4 Xo u0 {1,[S,D]}

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Kinetics family Surface_Adsorption_Bidentate: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Adsorption_Bidentate, a sample molecule made from node Adsorbate returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *1 H u0 p0 c-1 {2,D}
2 *2 H u0 p0 c-1 {1,D}


Origin Group AdjList:
1 *1 R u0 {2,[D,T]}
2 *2 R u0 {1,[D,T]}

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Kinetics family Surface_Recombination: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 97, in <lambda>
    test = lambda x: self.kinetics_checkSampleDescendsToGroup(family_name)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1047, in kinetics_checkSampleDescendsToGroup
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: In family Surface_Recombination, a sample molecule made from node Adsorbate1 returns an unexpectedly charged molecule:
Sample molecule AdjList:
1 *1 H u0 p0 c-1 {2,D}
2 *2 X u0 p0 c0 {1,D}


Origin Group AdjList:
1 *1 R  ux {2,[D,T]}
2 *2 Xo u0 {1,[D,T]}

--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Thermo groups adsorptionPt: nodes are in the tree with proper parents?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 139, in <lambda>
    test = lambda x: self.general_checkNodesFoundInTree(group_name, group)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1063, in general_checkNodesFoundInTree
    tst2.append((child in ascendParent.children, "Node {node} in {group} group was found in the tree without a proper parent.".format(node=nodeName, group=group_name)))
AttributeError: 'NoneType' object has no attribute 'children'

======================================================================
ERROR: Thermo groups adsorptionPt: nodes are nonidentical?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 145, in <lambda>
    test = lambda x: self.general_checkGroupsNonidentical(group_name, group)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1100, in general_checkGroupsNonidentical
    raise ValueError("Error Occurred")
ValueError: Error Occurred
-------------------- >> begin captured logging << --------------------
root: ERROR: Node O-*O-* in adsorptionPt group was found to be identical to node O*O*
--------------------- >> end captured logging << ---------------------

======================================================================
ERROR: Thermo groups adsorptionPt: parent-child relationships are correct?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 151, in <lambda>
    test = lambda x: self.general_checkChildParentRelationships(group_name, group)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1114, in general_checkChildParentRelationships
    tst1.append((group.matchNodeToChild(parentNode, childNode),
  File "/Users/rwest/Code/Cat/RMG-Py/rmgpy/data/base.py", line 886, in matchNodeToChild
    if isinstance(parentNode.item, Group) and isinstance(childNode.item, Group):
AttributeError: 'NoneType' object has no attribute 'item'

======================================================================
ERROR: Thermo groups adsorptionPt: Entry is accessible?
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/Users/rwest/anaconda/envs/rmg230/lib/python2.7/site-packages/nose/case.py", line 197, in runTest
    self.test(*self.arg)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 169, in <lambda>
    test = lambda x: self.general_checkSampleDescendsToGroup(group_name, group)
  File "/Users/rwest/Code/Cat/RMG-Py/testing/databaseTest.py", line 1237, in general_checkSampleDescendsToGroup
    sampleMolecule = entry.item.makeSampleMolecule()
  File "rmgpy/molecule/group.py", line 2386, in rmgpy.molecule.group.Group.makeSampleMolecule
    def makeSampleMolecule(self):
  File "rmgpy/molecule/group.py", line 2448, in rmgpy.molecule.group.Group.makeSampleMolecule
    newMolecule.update()
  File "rmgpy/molecule/molecule.py", line 977, in rmgpy.molecule.molecule.Molecule.update
    self.updateAtomTypes(logSpecies=log_species)
  File "rmgpy/molecule/molecule.py", line 1223, in rmgpy.molecule.molecule.Molecule.updateAtomTypes
    raise
  File "rmgpy/molecule/molecule.py", line 1218, in rmgpy.molecule.molecule.Molecule.updateAtomTypes
    atom.atomType = getAtomType(atom, atom.edges)
  File "rmgpy/molecule/atomtype.py", line 728, in rmgpy.molecule.atomtype.getAtomType
    def getAtomType(atom, bonds):
  File "rmgpy/molecule/atomtype.py", line 764, in rmgpy.molecule.atomtype.getAtomType
    raise AtomTypeError(
AtomTypeError: Unable to determine atom type for atom N-, which has 1 single bonds, 0 double bonds to C, 0 double bonds to O, 0 double bonds to S, 1 triple bonds, 0 benzene bonds, 0 lone pairs, and 1 charge.
-------------------- >> begin captured logging << --------------------
root: ERROR: Problem making sample molecule for group R*bidentate
1 R u0 {2,[S,D,T]} {3,[S,D,T]}
2 R u0 {1,[S,D,T]} {4,[S,D,T]}
3 X u0 {1,[S,D,T]}
4 X u0 {2,[S,D,T]}

root: ERROR: Could not update atomtypes for this molecule:
multiplicity -187
1 H u0 p0 c0 {2,S}
2 N u0 p1 c-1 {1,S} {3,T}
3 X u0 p0 c0 {2,T}

root: ERROR: Problem making sample molecule for group N#*R
1 N u0 {2,T} {3,[S,D]}
2 X u0 {1,T}
3 R u0 {1,[S,D]}

--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 1177 tests in 770.529s

FAILED (errors=11)

[alongd]

Also, we log too many debug messages by default, which makes it hard to see the important stuff. Can we consider reducing (or commenting out) database-related debug messages?

[rwest]

I feel like at some time I definitely agreed with Alon, but now I can't remember what made this happen. Looking at this databasetest.log (made with make test-database > databasetest.log 2>&1) then it seems that if you let nosetests do its thing of capturing output, then it just prints a load of lines like

Thermo groups group: Entry is accessible? ... ok
Thermo groups adsorptionPt: nodes are in the tree with proper parents? ... ERROR
Thermo groups adsorptionPt: nodes are nonidentical? ... ERROR
Thermo groups adsorptionPt: parent-child relationships are correct? ... ERROR
Thermo groups adsorptionPt: sibling relationships are correct? ... ok
Thermo groups adsorptionPt: Cd atomtype used correctly? ... ok

followed by the captured error messages which are needed to debug. Not too much distraction.

Is it a problem on travis? or certain tests print more messages? or if you run with --nocapture ?

Anyway, I'm not going to argue against an audit of uses of print / logging.debug / logging.info / logging.error

[mjohnson541]

Ok, most of those seem to just be issues where failing one assert (that used to end the test) makes it so the second/third tests can't be done. I've updated the branch with fixes for the cases identified here.

[mjohnson541]

So there isn't any debug code in the database tests, but there is in some of the database functions it calls so when some of the database tests fail the debug from those functions show up. I saw some of that debugging this test. Perhaps we can add that as a smaller part of the coming hackathon.

[rwest]

Ahh, that makes sense (where the debug messages come from). I knew I'd seen it some time. Could remove them, and/or change the logging level in databaseTest?

[mliu49]

#1597 added --nocapture and --nologcapture so we no longer get all of the debugging messages when tests fail.