Merge pull request #15 from martinghunt/better_logging

Better logging

minos/adjudicator.py

@@ -1,3 +1,4 @@
+import logging
 import os
 import shutil
 
@@ -47,7 +48,13 @@ def run(self):
         except:
             raise Error('Error making output directory ' + self.outdir)
 
-        dependencies.check_and_report_dependencies(self.log_file, programs=['gramtools'])
+        fh = logging.FileHandler(self.log_file, mode='w')
+        log = logging.getLogger()
+        formatter = logging.Formatter('[minos %(asctime)s %(levelname)s] %(message)s', datefmt='%d-%m-%Y %H:%M:%S')
+        fh.setFormatter(formatter)
+        log.addHandler(fh)
+        dependencies.check_and_report_dependencies(programs=['gramtools'])
+        logging.info('Dependencies look OK')
 
         clusterer = vcf_clusterer.VcfClusterer(
             self.vcf_files,
@@ -58,6 +65,8 @@ def run(self):
         )
         clusterer.run()
 
+        logging.info('Clustered VCF files, to make one VCF input file for gramtools')
+
         quasimap_dir = gramtools.run_gramtools(
             self.gramtools_outdir,
             self.clustered_vcf,
@@ -66,9 +75,12 @@ def run(self):
             self.max_read_length,
         )
 
+        logging.info('Loading gramtools quasimap output files ' + quasimap_dir)
         mean_depth, vcf_header, vcf_records, allele_coverage, allele_groups = gramtools.load_gramtools_vcf_and_allele_coverage_files(self.perl_generated_vcf, quasimap_dir)
+        logging.info('Finished loading gramtools files')
         sample_name = vcf_file_read.get_sample_name_from_vcf_header_lines(vcf_header)
         assert sample_name is not None
+        logging.info('Writing VCf output file ' + self.final_vcf)
         gramtools.write_vcf_annotated_using_coverage_from_gramtools(
             mean_depth,
             vcf_records,
@@ -79,3 +91,4 @@ def run(self):
             sample_name=sample_name,
         )
 
+        logging.info('All done! Thank you for using minos :)')

minos/dependencies.py

@@ -1,4 +1,5 @@
 import json
+import logging
 import os
 import shutil
 
@@ -123,14 +124,18 @@ def dependencies_report(programs=None):
     return all_ok, lines
 
 
-def check_and_report_dependencies(outfile, programs=None):
+def check_and_report_dependencies(outfile=None, programs=None):
     '''Writes report of depndencies to file (could be stdout).
     Raises error if any depndency not found'''
     all_ok, report_lines = dependencies_report(programs=programs)
-    f = pyfastaq.utils.open_file_write(outfile)
-    print(*report_lines, sep='\n', file=f)
-    print('All ok:', all_ok, file=f)
-    pyfastaq.utils.close(f)
+    if outfile is not None:
+        f = pyfastaq.utils.open_file_write(outfile)
+        print(*report_lines, sep='\n', file=f)
+        print('All ok:', all_ok, file=f)
+        pyfastaq.utils.close(f)
+    else:
+        for line in report_lines:
+            logging.info('Depencency check: ' + line)
     if not all_ok:
         raise Error('At least one dependency not found')
 

minos/gramtools.py

@@ -1,5 +1,6 @@
 import datetime
 import json
+import logging
 import os
 
 from cluster_vcf_records import vcf_file_read
@@ -44,15 +45,19 @@ def run_gramtools(output_dir, vcf_file, ref_file, reads, max_read_length):
         '--reference', ref_file,
         '--max-read-length', str(max_read_length),
     ])
+    logging.info('Running gramtools build: ' + build_command)
     utils.syscall(build_command)
+    logging.info('Finished running gramtools build')
 
     quasimap_command = ' '.join([
         gramtools_exe,
         'quasimap',
         '--gram-directory', output_dir,
         ' '.join(['--reads ' + x for x in reads]),
     ])
+    logging.info('Running gramtools quasimap: ' + quasimap_command)
     utils.syscall(quasimap_command)
+    logging.info('Finished running gramtools quasimap')
     return _get_quasimap_out_dir(output_dir)
 
 
@@ -126,6 +131,7 @@ def write_vcf_annotated_using_coverage_from_gramtools(mean_depth, vcf_records, a
         print('#CHROM', 'POS', 'ID', 'REF', 'ALT', 'QUAL', 'FILTER', 'INFO', 'FORMAT', sample_name, sep='\t', file=f)
 
         for i in range(len(vcf_records)):
+            logging.debug('Genotyping: ' + str(vcf_records[i]))
             update_vcf_record_using_gramtools_allele_depths(vcf_records[i], all_allele_coverage[i][0], all_allele_coverage[i][1], allele_groups, mean_depth, read_error_rate)
             print(vcf_records[i], file=f)
 

minos/tests/dependencies_test.py

@@ -88,15 +88,15 @@ def test_check_and_report_dependencies(self):
         tmpfile = 'tmp.check_and_report_dependencies.out'
         if os.path.exists(tmpfile):
             os.unlink(tmpfile)
-        dependencies.check_and_report_dependencies(tmpfile)
+        dependencies.check_and_report_dependencies(outfile=tmpfile)
         # We don't inow what the versions etc will be, so just
         # check file got written
         self.assertTrue(os.path.exists(tmpfile))
         os.unlink(tmpfile)
 
         os.environ['MINOS_BWA'] = 'oops_this_is_wrong'
         with self.assertRaises(dependencies.Error):
-            dependencies.check_and_report_dependencies(tmpfile)
+            dependencies.check_and_report_dependencies(outfile=tmpfile)
         del os.environ['MINOS_BWA']
         self.assertTrue(os.path.exists(tmpfile))
         os.unlink(tmpfile)

scripts/minos

@@ -11,9 +11,7 @@ parser = argparse.ArgumentParser(
 )
 
 parser.add_argument('--version', action='version', version=minos.__version__)
-log_group = parser.add_mutually_exclusive_group()
-log_group.add_argument( '-d', '--debug', help="Show debugging info (incompatible with --verbose)", action="store_const", dest="loglevel", const=logging.DEBUG, default=logging.WARNING)
-log_group.add_argument( '-v', '--verbose', help="Be verbose (incompatible with --debug)", action="store_const", dest="loglevel", const=logging.INFO)
+parser.add_argument('--debug', help="More verbose logging", action='store_true')
 
 
 subparsers = parser.add_subparsers(title='Available commands', help='', metavar='')
@@ -84,7 +82,13 @@ subparser_versions.set_defaults(func=minos.tasks.versions.run)
 
 
 args = parser.parse_args()
-logging.basicConfig(level=args.loglevel, format='[minos %(asctime)s %(levelname)s] %(message)s', datefmt='%d-%m-%Y %H:%M:%S')
+
+log = logging.getLogger()
+if args.debug:
+    log.setLevel(logging.DEBUG)
+else:
+    log.setLevel(logging.INFO)
+
 
 if hasattr(args, 'func'):
     args.func(args)