change: add --debug flag, replace all calls to print() with a streamhandler logger

CHANGELOG.md

@@ -1,3 +1,9 @@
+## dbt 0.6.1 (unreleased)
+
+#### Changes
+
+- add `--debug` flag, replace calls to `print()` with a global logger ([#256](https://github.com/analyst-collective/dbt/pull/256))
+
 ## dbt release 0.6.0
 
 ### tl;dr

dbt/compilation.py

@@ -1,17 +1,19 @@
-
 import os
 import fnmatch
 import jinja2
 from collections import defaultdict
+import time
+import sqlparse
+
 import dbt.project
-from dbt.source import Source
-from dbt.utils import find_model_by_fqn, find_model_by_name, dependency_projects, split_path, This, Var, compiler_error, to_string
-from dbt.linker import Linker
-from dbt.runtime import RuntimeContext
 import dbt.targets
 import dbt.templates
-import time
-import sqlparse
+
+from dbt.linker import Linker
+from dbt.logger import GLOBAL_LOGGER as logger
+from dbt.runtime import RuntimeContext
+from dbt.source import Source
+from dbt.utils import find_model_by_fqn, find_model_by_name, dependency_projects, split_path, This, Var, compiler_error, to_string
 
 CompilableEntities = ["models", "data tests", "schema tests", "archives", "analyses"]
 
@@ -174,10 +176,10 @@ def wrapped_do_ref(*args):
             except RuntimeError as e:
                 root = os.path.relpath(model.root_dir, model.project['project-root'])
                 filepath = os.path.join(root, model.rel_filepath)
-                print("Compiler error in {}".format(filepath))
-                print("Enabled models:")
+                logger.info("Compiler error in {}".format(filepath))
+                logger.info("Enabled models:")
                 for m in all_models:
-                    print(" - {}".format(".".join(m.fqn)))
+                    logger.info(" - {}".format(".".join(m.fqn)))
                 raise e
 
         return wrapped_do_ref

dbt/deprecations.py

@@ -1,4 +1,4 @@
-
+from dbt.logger import GLOBAL_LOGGER as logger
 
 class DBTDeprecation(object):
     name = None
@@ -7,12 +7,12 @@ class DBTDeprecation(object):
     def show(self, *args, **kwargs):
         if self.name not in active_deprecations:
             desc = self.description.format(**kwargs)
-            print("* Deprecation Warning: {}\n".format(desc))
+            logger.info("* Deprecation Warning: {}\n".format(desc))
             active_deprecations.add(self.name)
 
 class DBTRunTargetDeprecation(DBTDeprecation):
     name = 'run-target'
-    description = """profiles.yml configuration option 'run-target' is deprecated. Please use 'target' instead. 
+    description = """profiles.yml configuration option 'run-target' is deprecated. Please use 'target' instead.
   The 'run-target' option will be removed (in favor of 'target') in DBT version 0.7.0"""
 
 class DBTInvalidPackageName(DBTDeprecation):

dbt/logger.py

@@ -1,43 +1,24 @@
 import logging
-import logging.config
-import os
+import sys
 
-def make_log_dir_if_missing(log_dir):
-    if not os.path.exists(log_dir):
-        os.makedirs(log_dir)
+# disable logs from other modules, excepting ERROR logs
+logging.getLogger('contracts').setLevel(logging.ERROR)
+logging.getLogger('requests').setLevel(logging.ERROR)
+logging.getLogger('urllib3').setLevel(logging.ERROR)
 
-def getLogger(log_dir, name):
-    make_log_dir_if_missing(log_dir)
-    filename = "dbt.log"
-    base_log_path = os.path.join(log_dir, filename)
 
-    dictLogConfig = {
-        "version":1,
-        "handlers": {
-            "fileHandler":{
-                "class":"logging.handlers.TimedRotatingFileHandler",
-                "formatter":"fileFormatter",
-                "when": "d",  # rotate daily
-                "interval": 1,
-                "backupCount": 7,
-                "filename": base_log_path
-            },
-        },
-        "loggers":{
-            "dbt":{
-                "handlers":["fileHandler"],
-                "level":"DEBUG",
-                "propagate": False
-            }
-        },
+# create a global console logger for dbt
+handler = logging.StreamHandler(sys.stdout)
+handler.setFormatter(logging.Formatter('%(message)s'))
 
-        "formatters":{
-            "fileFormatter":{
-                "format":"%(asctime)s - %(name)s - %(levelname)s - %(threadName)s - %(message)s"
-            }
-        }
-    }
-    logging.config.dictConfig(dictLogConfig)
-    logger = logging.getLogger(name)
-    return logger
+logger = logging.getLogger()
+logger.addHandler(handler)
+logger.setLevel(logging.INFO)
 
+
+def initialize_logger(debug_mode=False,):
+    if debug_mode:
+        handler.setFormatter(logging.Formatter('%(asctime)-18s: %(message)s'))
+        logger.setLevel(logging.DEBUG)
+
+GLOBAL_LOGGER = logger

dbt/main.py

@@ -1,5 +1,5 @@
 
-from dbt.logger import getLogger
+from dbt.logger import initialize_logger, GLOBAL_LOGGER as logger
 
 import argparse
 import os.path
@@ -38,13 +38,15 @@ def main(args=None):
         return handle(args)
 
     except RuntimeError as e:
-        print("Encountered an error:")
-        print(str(e))
+        logger.info("Encountered an error:")
+        logger.info(str(e))
         sys.exit(1)
 
 def handle(args):
     parsed = parse_args(args)
 
+    initialize_logger(parsed.debug)
+
     # this needs to happen after args are parsed so we can determine the correct profiles.yml file
     if is_opted_out(parsed.profiles_dir):
         dbt.tracking.do_not_track()
@@ -76,7 +78,6 @@ def run_from_args(parsed):
     else:
 
         nearest_project_dir = get_nearest_project_dir()
-
         if nearest_project_dir is None:
             raise RuntimeError("fatal: Not a dbt project (or any of the parent directories). Missing dbt_project.yml file")
 
@@ -104,12 +105,16 @@ def invoke_dbt(parsed):
         proj = project.read_project('dbt_project.yml', parsed.profiles_dir, validate=False, profile_to_load=parsed.profile)
         proj.validate()
     except project.DbtProjectError as e:
-        print("Encountered an error while reading the project:")
-        print("  ERROR {}".format(str(e)))
-        print("Did you set the correct --profile? Using: {}".format(parsed.profile))
+        logger.info("Encountered an error while reading the project:")
+        logger.info("  ERROR {}".format(str(e)))
+        logger.info("Did you set the correct --profile? Using: {}".format(parsed.profile))
+
+        logger.info("Valid profiles:")
+
         all_profiles = project.read_profiles(parsed.profiles_dir).keys()
-        profiles_string = "\n".join([" - " + key for key in all_profiles])
-        print("Valid profiles:\n{}".format(profiles_string))
+        for profile in all_profiles:
+            logger.info(" - {}".format(profile))
+
         dbt.tracking.track_invalid_invocation(project=proj, args=parsed, result_type="invalid_profile", result=str(e))
         return None
 
@@ -118,16 +123,15 @@ def invoke_dbt(parsed):
         if parsed.target in targets:
             proj.cfg['target'] = parsed.target
         else:
-            print("Encountered an error while reading the project:")
-            print("  ERROR Specified target {} is not a valid option for profile {}".format(parsed.target, proj.profile_to_load))
-            print("Valid targets are: {}".format(targets))
+            logger.info("Encountered an error while reading the project:")
+            logger.info("  ERROR Specified target {} is not a valid option for profile {}".format(parsed.target, proj.profile_to_load))
+            logger.info("Valid targets are: {}".format(targets))
             dbt.tracking.track_invalid_invocation(project=proj, args=parsed, result_type="invalid_target", result="target not found")
             return None
 
     log_dir = proj.get('log-path', 'logs')
-    logger = getLogger(log_dir, __name__)
 
-    logger.info("running dbt with arguments %s", parsed)
+    logger.debug("running dbt with arguments %s", parsed)
 
     task = parsed.cls(args=parsed, project=proj)
 
@@ -136,6 +140,8 @@ def invoke_dbt(parsed):
 def parse_args(args):
     p = argparse.ArgumentParser(prog='dbt: data build tool', formatter_class=argparse.RawTextHelpFormatter)
     p.add_argument('--version', action='version', version=dbt.version.get_version_information(), help="Show version information")
+    p.add_argument('-d', '--debug', action='store_true', help='Display debug logging during dbt execution. Useful for debugging and making bug reports.')
+
     subs = p.add_subparsers()
 
     base_subparser = argparse.ArgumentParser(add_help=False)
@@ -184,7 +190,10 @@ def parse_args(args):
     sub.add_argument('--threads', type=int, required=False, help="Specify number of threads to use while executing tests. Overrides settings in profiles.yml")
     sub.set_defaults(cls=test_task.TestTask, which='test')
 
-    if len(args) == 0: return p.print_help()
+    if len(args) == 0:
+        p.print_help()
+        sys.exit(1)
 
     parsed = p.parse_args(args)
+
     return parsed