added filehandlers to UnitTest logging, cleaned up some output messages

testing/UnitTest.py

@@ -17,13 +17,7 @@
 
 # Make a global logging object.
 logger = logging.getLogger('InterMolLog')
-logger.setLevel(logging.INFO) # specifies lowest severity log messages to handle (DEBUG will be ignored)
-h = logging.StreamHandler()
-#f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s")
-f = logging.Formatter("%(levelname)s %(asctime)s %(message)s", "%Y-%m-%d %H:%M:%S")
-h.setFormatter(f)
-logger.addHandler(h)
-
+logger.setLevel(logging.DEBUG)
 
 def parse_args():
     parser = argparse.ArgumentParser(prog='PROG',
@@ -76,6 +70,26 @@ def add_flags(args, flags):
         flags.append(args.lmppath)
     return flags
 
+def add_handler(dir):
+    logger = logging.getLogger('InterMolLog')
+    h1 = logging.FileHandler('%s/UnitTestInfo.log' % dir, mode='w') # don't append to existing file
+    f1 = logging.Formatter("%(levelname)s %(asctime)s %(message)s", "%Y-%m-%d %H:%M:%S")
+    h1.setFormatter(f1)
+    h1.setLevel(logging.INFO)
+    logger.addHandler(h1)
+
+    h2 = logging.FileHandler('%s/UnitTestDebug.log' % dir, mode='w')
+    f2 = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s", "%Y-%m-%d %H:%M:%S")
+    h2.setFormatter(f2)
+    h2.setLevel(logging.DEBUG)
+    logger.addHandler(h2)
+    return h1, h2
+
+def remove_handler(h1, h2):
+    logger = logging.getLogger('InterMolLog')
+    logger.removeHandler(h1)
+    logger.removeHandler(h2)
+
 def test_desmond(args):
     logger = logging.getLogger('InterMolLog')
     files = sorted(glob.glob('%s/*/*.cms' % DES_IN)) # return list of files that match the string
@@ -91,17 +105,18 @@ def test_desmond(args):
         odir = '%s/%s' % (basedir, prefix)
         if not os.path.isdir(odir):
             os.mkdir(odir)
+        h1, h2 = add_handler(odir)
         flags = ['--des_in', f, '--desmond', '--gromacs', '--lammps', '--odir', odir]
         flags = add_flags(args, flags)
-        logger.info('converting %s with command' % f)
-        logger.info('python convert.py ' + ' '.join(flags))
+        logger.info('Converting %s with command:\n    python convert.py %s' % (f,' '.join(flags)))
         try:
             diff = convert.main(flags) # reuses code from convert.py
             assert(len(diff) == N_FORMATS)
             results += diff
         except Exception as e:
             logger.exception(e)
             results += [e]*N_FORMATS
+        remove_handler(h1, h2)
     return files, results
 
 def test_gromacs(args):
@@ -120,17 +135,19 @@ def test_gromacs(args):
         odir = '%s/%s' % (basedir, prefix)
         if not os.path.isdir(odir):
             os.mkdir(odir)
+        h1, h2 = add_handler(odir)
         flags = ['--gro_in', g, t, '--desmond', '--gromacs', '--lammps', '--odir', odir]
         flags = add_flags(args, flags)
-        logger.info('converting {0}, {1} with command'.format(g,t))
-        logger.info('python convert.py ' + ' '.join(flags))
+        logger.info('Converting %s, %s with command:\n    python convert.py %s' 
+                    % (g, t,' '.join(flags)))
         try:
             diff = convert.main(flags) # reuses code from convert.py
             assert(len(diff) == N_FORMATS)
             results += diff
         except Exception as e:
             logger.exception(e)
             results += [e]*N_FORMATS
+        remove_handler(h1, h2)
     return gro_files, results
 
 def test_lammps(args):
@@ -147,17 +164,18 @@ def test_lammps(args):
         odir = '%s/%s' % (basedir, prefix)
         if not os.path.isdir(odir):
             os.mkdir(odir)
+        h1, h2 = add_handler(odir)
         flags = ['--lmp_in', f, '--desmond', '--gromacs', '--lammps', '--odir', odir]
         flags = add_flags(args, flags)
-        logger.info('converting %s to desmond file format with command' % f)
-        logger.info('python convert.py ' + ' '.join(flags))
+        logger.info('Converting %s with command:\n    python convert.py %s' % (f,' '.join(flags)))
         try:
             diff = convert.main(flags) # reuses code from convert.py
             assert(len(diff) == N_FORMATS)
             results += diff
         except Exception as e:
             logger.exception(e)
             results += [e]*N_FORMATS
+        remove_handler(h1, h2)
     return files, results
 
 def summarize_results(input_type, files, results):
@@ -192,6 +210,9 @@ def summarize_results(input_type, files, results):
     for f,r in zip(files, lmp_res):
         print '{:{}}   {:>{}}'.format(f, col1_width, r, col2_width)
     print ''
+    print 'See %s/From%s/*/UnitTestInfo.log for the standard output of each conversion' % (OUTPUT_DIR, input_type)
+    print 'See %s/From%s/*/UnitTestDebug.log for a detailed DEBUG-level log of each conversion' % (OUTPUT_DIR, input_type)
+    print ''
 
 def main():
     args = parse_args()

testing/convert.py

@@ -210,12 +210,13 @@ def main(args=''):
                 e_outfile.append(-1)
 
         # display energy comparison results
-        print ''
-        print '{0} input energy file: {1}'.format(input_type, e_infile)
+        out = ['']
+        out.append('{0} input energy file: {1}'.format(input_type, e_infile))
         for type, file in zip(output_type, e_outfile):
-            print '{0} output energy file: {1}'.format(type, file)
-        helper_functions.print_multiple_energy_results(e_in, e_out, input_type, output_type)
-    status = [x if x else 'Converted' for x in status] # changes 0 to 'Converted'
+            out.append('{0} output energy file: {1}'.format(type, file))
+        out += helper_functions.summarize_energy_results(e_in, e_out, input_type, output_type)
+        logger.info('\n'.join(out))
+    status = ['Converted' if x is 0 else x for x in status] # changes 0 to 'Converted'
     return status
 
 if __name__ == '__main__':

testing/desmond_driver.py

@@ -9,7 +9,7 @@
 
 def readFile(infile):
     logger = logging.getLogger('InterMolLog')
-    logger.info('Reading in Desmond structure {0}'.format(infile))
+    logger.info('Reading DESMOND file {0}'.format(infile))
     parser = DesmondParser()
     parser.readFile(infile)
     logger.info('Structure loaded')
@@ -116,14 +116,14 @@ def desmond_energies(cms, cfg, despath):
     if os.path.exists('trj'):
         shutil.rmtree('trj')
     cmd = [desmond_bin, '-WAIT', '-P', '1', '-in', cms, '-JOBNAME', name, '-c', cfg]
-    logger.debug('Running DESMOND with command')
-    logger.debug(' '.join(cmd))
+    logger.debug('Running DESMOND with command:\n    %s' % ' '.join(cmd))
     with open('desmond_stdout.txt','w') as out, open('desmond_stderr.txt','w') as err:
         exit = subprocess.call(cmd, stdout=out, stderr=err)
     os.chdir(cwd)
 
     if exit: # exit status not 0
-        raise Exception('Failed evaluating energy of {0}'.format(cms))
+        logger.error('Energy evaluation failed. See %s/desmond_stderr.txt' % direc)
+        raise Exception('Energy evaluation failed for {0}'.format(cms))
 
     # parse desmond energy file
     tot_energy = get_desmond_energy_from_file(energy_file)

testing/gromacs_driver.py

@@ -14,11 +14,11 @@ def readFile(top_in, gro_in, gropath):
     gromacs_energies(top_in, gro_in,
             'Inputs/Gromacs/grompp.mdp', gropath, '',
             grompp_check=True)
-    logger.info('Reading in Gromacs topology {0}...'.format(top_in))
+    logger.info('Reading GROMACS topology {0}'.format(top_in))
     GromacsTopologyParser._GroTopParser = GromacsTopologyParser()
     GromacsTopologyParser._GroTopParser.parseTopology(top_in)
     logger.info('Topology loaded')
-    logger.info('Reading in Gromacs structure {0}...'.format(gro_in))
+    logger.info('Reading GROMACS structure {0}'.format(gro_in))
     GromacsStructureParser.readStructure(gro_in)
     logger.info('Structure loaded')
 
@@ -60,34 +60,34 @@ def gromacs_energies(top=None, gro=None, mdp=None, gropath='',grosuff='', grompp
 
     # grompp'n it up
     cmd = [grompp_bin, '-f', mdp, '-c', gro, '-p', top, '-o', tpr, '-po', mdout, '-maxwarn', '1']
-    logger.debug('Running GROMACS with command:')
-    logger.debug(' '.join(cmd))
+    logger.debug('Running GROMACS with command:\n    %s' % ' '.join(cmd))
     with open(stdout, 'w') as out, open(stderr, 'w') as err:
         exit = subprocess.call(cmd, stdout=out, stderr=err)
     if exit:
+        logger.error('grompp failed. See %s' % stderr)
         raise Exception('grompp failed for {0}'.format(top))
     if grompp_check:
         return
 
     # mdrunin'
     cmd = [mdrun_bin, '-nt', '1', '-s', tpr, '-o', traj, '-cpo', state, '-c', 
         conf, '-e', ener, '-g', log]
-    logger.debug('Running GROMACS with command:')
-    logger.debug(' '.join(cmd))
+    logger.debug('Running GROMACS with command:\n    %s' % ' '.join(cmd))
     with open(stdout, 'wa') as out, open(stderr, 'wa') as err:
         exit = subprocess.call(cmd, stdout=out, stderr=err)
     if exit:
+        logger.error('mdrun failed. See %s' % stderr)
         raise Exception('mdrun failed for {0}'.format(top))
 
     # energizin'
     select = " ".join(map(str, range(1, 20))) + " 0 "
     cmd = 'echo {select} | {genergy_bin} -f {ener} -o {ener_xvg} -dp'.format(
             select=select, genergy_bin=genergy_bin, ener=ener, ener_xvg=ener_xvg)
-    logger.debug('Running GROMACS with command:')
-    logger.debug(cmd)
+    logger.debug('Running GROMACS with command:\n    %s' % ' '.join(cmd))
     with open(stdout, 'wa') as out, open(stderr, 'wa') as err:
         exit = subprocess.call(cmd, stdout=out, stderr=err, shell=True)
     if exit:
+        logger.error('g_energy failed. See %s' % stderr)
         raise Exception('g_energy failed for {0}'.format(top))
 
     # extract g_energy output and parse initial energies

testing/helper_functions.py

@@ -3,6 +3,15 @@
 import pdb
 
 def get_diff(e_in, e_out):
+    '''returns difference in potential energy
+    
+    arguments:
+        e_in  - dictionary of energy groups from input file
+        e_out - dictionary of energy groups from output file
+    
+    returns:
+        potential energy difference in units of the input
+    '''
     type = 'Potential' # getting difference in potential energy
     input = e_in[type]
     diff = e_out[type].in_units_of(input.unit) - input
@@ -15,16 +24,27 @@ def find_match(key, dict, unit):
     else:
         return np.nan
 
-def print_multiple_energy_results(energy_input, energy_outputs, input_type, output_types):
+def summarize_energy_results(energy_input, energy_outputs, input_type, output_types):
+    ''' creates a table comparing input and output energy groups
+
+    args:
+        energy_input  - dictionary of energy groups from input file
+        energy_output - list containing dictionary of energy groups or -1 for each output file
+        input_type    - input format string
+        output_types  - list containing output formats
+    returns:
+        out - list of strings which forms a summary table using "\n".join(out) 
+    '''
+    out = []
     # remove failed evaluations (-1 in energy_outputs)
     failed_i = [i for i,x in enumerate(energy_outputs) if x == -1]
     failed = [output_types[i] for i in failed_i]
     output_types = [x for i,x in enumerate(output_types) if i not in failed_i]
     energy_outputs = [x for x in energy_outputs if x != -1]
     # find all distinct labels
     labels = set(energy_input.keys())
-    for out in energy_outputs:
-        for key, value in out.iteritems():
+    for e_out in energy_outputs:
+        for key, value in e_out.iteritems():
             labels.add(key)
     # set up energy comparison table
     labels = list(labels)
@@ -36,37 +56,33 @@ def print_multiple_energy_results(energy_input, energy_outputs, input_type, outp
             data[i,j] = find_match(labels[i], energy_all[j], unit)
     # sort table <= To do
     # print table
-    print '======================================================================='
-    print 'Summary statistics'
+    out.append('')
+    out.append('Energy Group Summary')
+    out.append('=======================================================================')
     header = '%20s %18s ' % ('Type', 'Input (%s)' % input_type)
-    for out in output_types:
-        header += '%37s' %('Output (%s) Diff (%s)' % (out, out))
-    print header
+    for otype in output_types:
+        header += '%37s' %('Output (%s) Diff (%s)' % (otype, otype))
+    out.append(header)
     for i in range(len(data)):
         line = '%20s ' % labels[i]
         line += '%18.8f ' % data[i][0]
         for j in range(1,len(data[i])):
             line += '%18.8f %18.8f' % (data[i][j],data[i][j]-data[i][0])
-        print line
-    print ''
+        out.append(line)
+    out.append('')
     # get differences in potential energy
     i = labels.index('Potential')
     diff = data[i,1::] - data[i,0]
-    for d, out in zip(diff, output_types):
-        print 'Difference in potential energy from %s=>%s conversion: %18.8f' % (input_type, out, d)
-    for out in failed:
-        print 'Energy comparison for {0} output FAILED'.format(out)
-    print ''
-    print '======================================================================='
-    print ''
-    # insert error code for failed evaluations
-    diff = diff.tolist()
-    for i in failed_i:
-        diff.insert(i,4)
-    return diff
+    for d, otype in zip(diff, output_types):
+        out.append('Difference in potential energy from %s=>%s conversion: %18.8f' 
+                    % (input_type, otype, d))
+    for f in failed:
+        out.append('Energy comparison for {0} output FAILED'.format(f))
+    out.append('=======================================================================')
+    return out
 
 def combine_energy_results(e_in, e_out):
-    '''
+    '''deprecated
     '''
     data = OrderedDict()
     matches = []
@@ -99,7 +115,7 @@ def combine_energy_results(e_in, e_out):
     return data, rms
 
 def print_energy_summary(results):
-    '''
+    '''deprecated
     '''
     data, rms = results
     print '======================================================================='

testing/lammps_driver.py

@@ -7,20 +7,19 @@
 
 def readFile(infile):
     logger = logging.getLogger('InterMolLog')
-    logger.info('Reading LAMMPS data & input files...')
+    logger.info('Reading LAMMPS files {0}'.format(infile))
     parser = LammpsParser()
     parser.read_system(infile)
     logger.info('Structure loaded')
 
 def writeFile(outfile):
     logger = logging.getLogger('InterMolLog')
-    logger.info('Converting to LAMMPS file {0}'.format(outfile))
+    logger.info('Writing LAMMPS file {0}'.format(outfile))
     parser = LammpsParser()
     parser.write(outfile)
     logger.info('Write complete')
 
-def lammps_energies(input_file, lmppath='lmp_openmpi',
-        verbose=False):
+def lammps_energies(input_file, lmppath='lmp_openmpi'):
     """Evaluate energies of LAMMPS files
 
     Args:
@@ -38,11 +37,13 @@ def lammps_energies(input_file, lmppath='lmp_openmpi',
 
     cmd = "{lmppath} < {input_file}".format(
             lmppath=lmppath, input_file=input_file)
+    logger.debug('Running LAMMPS with command:\n    %s' % cmd)
     with open('lammps_stdout.txt', 'w') as out, open('lammps_stderr.txt', 'w') as err:
         exit = subprocess.call(cmd, stdout=out, stderr=err, shell=True)
     os.chdir(saved_path)
     if exit:
-        raise Exception('Lammps evaluation failed for {0}'.format(input_file))
+        logger.error('Energy evaluation failed. See %s/lammps_stderr.txt' % directory)
+        raise Exception('Energy evaluation failed for {0}'.format(input_file))
 
     # energizin'
     proc = subprocess.Popen(["awk '/E_bond/{getline; print}' %s/lammps_stdout.txt" % (directory)],