add --debug flag, replace all calls to print() with a streamhandl…

…er logger (#256)

Adds a `--debug` (`-d`) flag, which displays debug logging during dbt execution. Useful for debugging and making bug reports.

Removes the `logs/` directory. If you want logs, use the debug flag instead.

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:/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