Debug logging.

app/__init__.py

@@ -10,14 +10,6 @@ import datetime
 import logging
 import datetime
 
-logger = logging.getLogger('rarefan')
-formatter = logging.Formatter('%(asctime)s [%(levelname)s] %(module)s: %(message)s')
-timestamp = datetime.datetime.now().strftime(format="%Y%m%d-%H%M%S")
-handler = logging.FileHandler("/tmp/rarefan.log".format(timestamp))
-handler.setFormatter(formatter)
-handler.setLevel(logging.DEBUG)
-logger.addHandler(handler)
-
 app = Flask(__name__, instance_relative_config=True, static_url_path='/static')
 upload_dir = os.path.join(app.static_folder, 'uploads')
 
@@ -27,6 +19,19 @@ app.testing = app.debug = True
 app.config.from_object(Config)
 app.config['UPLOAD_DIR'] = upload_dir
 
+# Logging
+logger = logging.getLogger('rarefan')
+formatter = logging.Formatter('%(asctime)s [%(levelname)s] %(module)s: %(message)s')
+timestamp = datetime.datetime.now().strftime(format="%Y%m%d-%H%M%S")
+handler = logging.FileHandler("/tmp/rarefan.log".format(timestamp))
+handler.setFormatter(formatter)
+handler.setLevel(logging.INFO)
+if app.debug:
+    handler.setLevel(logging.DEBUG)
+
+logger.addHandler(handler)
+
+
 # csrf = CSRFProtect()
 # csrf.init_app(app)
 
@@ -42,3 +47,4 @@ app.queue = rq.Queue('rarefan', connection=app.redis)
 
 # Has to be the last import to avoid cyclic dependencies.
 from app import views, routes
+

app/callbacks/callbacks.py

@@ -6,8 +6,7 @@ from app.tasks.email import email_task
 from app.tasks.zip import zip_task
 
 import logging
-logging.basicConfig(level=logging.DEBUG)
-
+logger = logging.getLogger('rarefan')
 
 def rarefan_on_success(job, result):
     """ Callback for the 'rarefan' task if completed successfully. """
@@ -55,11 +54,11 @@ def on_success(job, connection, result, *args, **kwargs):
 def on_failure(job, connection, type, value, traceback):
     """ Generic failure callback for all tasks. """
 
-    logging.debug(job.id)
-    logging.debug(job.meta)
-    logging.debug(type)
-    logging.debug(value)
-    logging.debug(traceback)
+    logger.debug(job.id)
+    logger.debug(job.meta)
+    logger.debug(type)
+    logger.debug(value)
+    logger.debug(traceback)
 
     dbjob_id = job.meta['dbjob_id']
     stage = job.meta['stage']

app/models.py

@@ -6,7 +6,8 @@ import sys
 import rq
 from rq.exceptions import NoSuchJobError
 import logging
-logging.basicConfig(level=logging.DEBUG)
+
+logger = logging.getLogger('rarefan')
 
 from app import app, db
 
@@ -54,7 +55,7 @@ class Job(db.Document):
         stage_names =  self.stages.keys()
         for stage in stage_names:
             self.set_status(stage)
-            logging.debug("%s status= %s", stage, self.stages[stage]['status'] )
+            logger.debug("%s status= %s", stage, self.stages[stage]['status'] )
         
         overall = 'setup'
         if all([ stage['status'] == "none" for stage in self.stages.values()]):

app/routes.py

@@ -12,8 +12,6 @@ from werkzeug.utils import secure_filename
 import rq
 from rq.job import Job as RQJob
 
-import time
-
 from app.views import SubmitForm, AnalysisForm, UploadForm, ReturnToResultsForm, RunForm
 from app import app, db
 from app.models import Job as DBJob
@@ -22,19 +20,19 @@ from app.tasks.tree import tree_task, empty_task
 from app.tasks.zip import zip_task
 from app.tasks.email import email_task
 from app.tasks.redis_tests import example
-
 from app.callbacks.callbacks import on_success, on_failure
 
-import logging
-import datetime
+from Bio import SeqIO
 import copy
+import datetime
+import logging
 import os
 import shlex
 import shutil
 import stat
 import subprocess
 import tempfile
-from Bio import SeqIO
+import time
 
 logger = logging.getLogger('rarefan')
 
@@ -403,7 +401,7 @@ def files(req_path):
         # Remove trailing '/'
         if req_path.endswith('/'):
             req_path = req_path[:-1]
-        logger.warning("Request dir is %s in (%s).", req_path, os.path.dirname(req_path))
+        logger.info("Request dir is %s in (%s).", req_path, os.path.dirname(req_path))
 
         # Save the target for the 'back to results' link.
         tmp_dir = session.get('tmpdir', None)

app/tasks/email.py

-import subprocess
+""" :module email: Hosts the redis email task to send out job completion notifications to configured email addresses."""
+
 import copy
 import os
-import sys
+import re
 import shlex
 import shutil
-import re
 import subprocess
+import subprocess
+import sys
 
 from app import app
 from app.utilities import checkers
@@ -18,7 +20,7 @@ from app.models import Job as DBJob
 
 import jinja2
 import logging
-logging.basicConfig(level=logging.DEBUG)
+logger = logging.getLogger('rarefan')
 
 app.app_context().push()
 
@@ -34,8 +36,8 @@ def email_test():
 
     success = mail.send(message)
 
-    logging.debug("Mail was sent: %s", str(success))
-    logging.debug("Mail message was: %s", str(message))
+    logger.debug("Mail was sent: %s", str(success))
+    logger.debug("Mail message was: %s", str(message))
 
     return success, message
 
@@ -57,7 +59,7 @@ def email_task(run_id):
 
     # Only non-empty strings in recipients list.
     recipients = [rec for rec in recipients if rec != ""]
-    logging.debug("Recipients: %s", recipients)
+    logger.debug("Recipients: %s", recipients)
 
     # Simply return if no recipients configured.
     if len(recipients) == 0:
@@ -75,7 +77,6 @@ def email_task(run_id):
 
     email_body = template.render(job=dbjob)  # this is where to put args to the template renderer
 
-
     sender = app.config['DEFAULT_MAIL_SENDER']
 
     message = Message(subject=email_subject,
@@ -83,18 +84,18 @@ def email_task(run_id):
                       sender=sender,
                       recipients=recipients,
                       )
-    logging.debug("Message: %s", message)
+    logger.debug("Message: %s", message)
 
     is_sent = copy.deepcopy(dbjob.notification_is_sent)
     while not is_sent:
         mail_status = mail.send(message)
-        logging.debug("Mail status %s", str(mail_status))
-        logging.debug("Mail status type: %s", str(type(mail_status)))
+        logger.debug("Mail status %s", str(mail_status))
+        logger.debug("Mail status type: %s", str(type(mail_status)))
 
         if mail_status is None:
-            logging.debug("Updating Mail status.")
+            logger.debug("Updating Mail status.")
             is_sent = True
     dbjob.update(set__notification_is_sent=copy.deepcopy(is_sent))
     dbjob.save()
 
-    logging.debug("Mail sent? %s", str(is_sent))
+    logger.debug("Mail sent? %s", str(is_sent))

app/tasks/rarefan.py

@@ -8,7 +8,7 @@ import subprocess
 from app.models import Job as DBJob
 from rq import get_current_job
 import logging
-logging.getLogger('rarefan')
+logger = logging.getLogger('rarefan')
 
 from app.utilities.rarefan_cli import rarefan_command
 
@@ -16,15 +16,15 @@ def rarefan_task(**kwargs):
     """Run the rarefan java code with arguments."""
 
     for k,v in kwargs.items():
-        logging.debug("%s = %s", k, str(v))
+        logger.debug("%s = %s", k, str(v))
 
     java_command = rarefan_command(**kwargs) 
 
-    logging.info("Java command: %s", java_command)
+    logger.info("Java command: %s", java_command)
 
     redis_job = get_current_job()
-    logging.debug("In rarefan.py, redis job id = %s", redis_job.id)
-    logging.debug("In rarefan.py, redis job meta = %s", str(redis_job.meta))
+    logger.debug("In rarefan.py, redis job id = %s", redis_job.id)
+    logger.debug("In rarefan.py, redis job meta = %s", str(redis_job.meta))
     dbjob = DBJob.objects.get(run_id=redis_job.meta['run_id'])
     dbjob.set_status('rarefan')
 

app/tasks/redis_tests.py

+# usage: $> rq enqueue -p app.tasks.redis_tests example 10
 import time
 
 import logging
 logger = logging.getLogger()
+
 def example(seconds):
     seconds=int(seconds)
     for i in range(seconds):
         logger.debug(i)
         time.sleep(1)
-    logging.debug("Done")
-# example(10)
+    logger.debug("Done")

app/tasks/tree.py

@@ -7,7 +7,7 @@ from app.models import Job as DBJob
 from rq import get_current_job
 
 import logging
-logging.getLogger('rarefan')
+logger = logging.getLogger('rarefan')
 
 def tree_task(run_dir, treefile=None):
     """ Generate a phylogenetic tree from all DNA sequence files in given directory.
@@ -28,7 +28,7 @@ def tree_task(run_dir, treefile=None):
     inputs = [os.path.join(run_dir, f) for f in os.listdir(run_dir) if f.split(".")[-1] in ["fas", "fna", "fn", "fasta", "fastn"]]
 
     for f in inputs:
-        logging.debug("Found sequence file %s.", f)
+        logger.debug("Found sequence file %s.", f)
 
     # Check if treefile exists.
     if treefile is None or treefile == "None":
@@ -48,7 +48,7 @@ def tree_task(run_dir, treefile=None):
     dbjob = DBJob.objects.get(run_id=redis_job.meta['run_id'])
     dbjob.set_status('tree')
 
-    logging.debug("tree generation command: %s", command)
+    logger.debug("tree generation command: %s", command)
 
     proc = subprocess.Popen(command,
                             stdout=subprocess.PIPE,

app/tasks/zip.py

@@ -7,7 +7,7 @@ import shutil
 from app.models import Job as DBJob
 from rq import get_current_job
 import logging
-logging.getLogger('rarefan')
+logger = logging.getLogger('rarefan')
 
 
 def zip_task(run_dir):
@@ -21,7 +21,9 @@ def zip_task(run_dir):
 
     """
     oldwd = os.getcwd()
+    logger.debug("Saving old WD %s", oldwd)
     os.chdir(run_dir)
+    logger.debug("Chdir to %s", os.getcwd())
     run_id = os.path.split(run_dir)[-1]
     zip_command = " ".join(["zip",
                                 "-r",
@@ -30,6 +32,7 @@ def zip_task(run_dir):
                                 ]
                                )
 
+    logger.debug("zip command: %s", zip_command)
     redis_job =  get_current_job()
     dbjob = DBJob.objects.get(run_id=redis_job.meta['run_id'])
     dbjob.set_status('zip')
@@ -41,11 +44,15 @@ def zip_task(run_dir):
 
     log, err = proc.communicate()
 
+    logger.debug("proc.stdout: %s", log)
+    logger.debug("proc.stderr: %s", err)
+
     # Append only stderr to logfile.
     with open(os.path.join('out', 'rarefan.log'), 'ab') as fh:
         fh.write(err)
 
     os.chdir(oldwd)
+    logger.debug("Chdir to %s", os.getcwd())
 
     return {'returncode': proc.returncode, "log": log}
 

app/utilities/checkers.py

 import sys
 import os
 import logging
-logger = logging.getLogger('routes')
+logger = logging.getLogger('rarefan')
 
 
 def count_lines(fname):
@@ -16,7 +16,7 @@ def count_lines(fname):
         try:
             number_of_lines = len(fh.readlines())
         except IOError:
-            logging.warning("%s is empty.", fname)
+            logger.warning("%s is empty.", fname)
             return 0
 
     return number_of_lines