Merge pull request #999 from gavindsouza/bench-logger

fix(logging): cleaner bench logs

bench/app.py

@@ -23,8 +23,7 @@ from bench.config.common_site_config import get_config
 from bench.utils import CommandFailedError, build_assets, check_git_for_shallow_clone, exec_cmd, get_cmd_output, get_frappe, restart_supervisor_processes, restart_systemd_processes, run_frappe_cmd
 
 
-logging.basicConfig(level="INFO")
+logger = logging.getLogger(bench.PROJECT_NAME)
-logger = logging.getLogger(__name__)
 
 
 class InvalidBranchException(Exception): pass
@@ -140,7 +139,7 @@ Do you want to continue and overwrite it?'''.format(repo_name)):
 			install_app(app=app_name, bench_path=bench_path, verbose=verbose, skip_assets=skip_assets)
 			sys.exit()
 
-	logger.info('Getting app {0}'.format(repo_name))
+	logger.log('Getting app {0}'.format(repo_name))
 	exec_cmd("git clone {git_url} {branch} {shallow_clone} --origin upstream".format(
 		git_url=git_url,
 		shallow_clone=shallow_clone,
@@ -165,7 +164,7 @@ def get_app_name(bench_path, repo_name):
 def new_app(app, bench_path='.'):
 	# For backwards compatibility
 	app = app.lower().replace(" ", "_").replace("-", "_")
-	logger.info('creating new app {}'.format(app))
+	logger.log('creating new app {}'.format(app))
 	apps = os.path.abspath(os.path.join(bench_path, 'apps'))
 	bench.set_frappe_version(bench_path=bench_path)
 
@@ -178,7 +177,7 @@ def new_app(app, bench_path='.'):
 
 
 def install_app(app, bench_path=".", verbose=False, no_cache=False, postprocess=True, skip_assets=False):
-	logger.info("installing {}".format(app))
+	logger.log("installing {}".format(app))
 
 	pip_path = os.path.join(bench_path, "env", "bin", "pip")
 	quiet_flag = "-q" if not verbose else ""
@@ -272,7 +271,7 @@ Here are your choices:
 				add_to_excluded_apps_txt(app, bench_path=bench_path)
 				print("Skipping pull for app {}, since remote doesn't exist, and adding it to excluded apps".format(app))
 				continue
-			logger.info('pulling {0}'.format(app))
+			logger.log('pulling {0}'.format(app))
 			if reset:
 				exec_cmd("git fetch --all", cwd=app_dir)
 				exec_cmd("git reset --hard {remote}/{branch}".format(

bench/cli.py

@@ -14,9 +14,8 @@ import bench
 from bench.app import get_apps
 from bench.commands import bench_command
 from bench.config.common_site_config import get_config
-from bench.utils import PatchError, bench_cache_file, check_latest_version, drop_privileges, find_parent_bench, generate_command_cache, get_cmd_output, get_env_cmd, get_frappe, is_bench_directory, is_dist_editable, is_root, log
+from bench.utils import PatchError, bench_cache_file, check_latest_version, drop_privileges, find_parent_bench, generate_command_cache, get_cmd_output, get_env_cmd, get_frappe, is_bench_directory, is_dist_editable, is_root, log, setup_logging
 
-logger = logging.getLogger(bench.PROJECT_NAME)
 from_command_line = False
 change_uid_msg = "You should not run this command as root"
 
@@ -24,8 +23,11 @@ change_uid_msg = "You should not run this command as root"
 def cli():
 	global from_command_line
 	from_command_line = True
+	command = " ".join(sys.argv)
 
 	change_working_directory()
+	logger = setup_logging() or logging.getLogger(bench.PROJECT_NAME)
+	logger.info(command)
 	check_uid()
 	change_dir()
 	change_uid()
@@ -56,7 +58,8 @@ def cli():
 
 	try:
 		bench_command()
-	except PatchError:
+	except BaseException as e:
+		logger.warn("{0} executed with exit code {1}".format(command, getattr(e, "code", None)))
 		sys.exit(1)
 
 

bench/commands/__init__.py

@@ -14,10 +14,7 @@ def print_bench_version(ctx, param, value):
 @click.option('--version', is_flag=True, is_eager=True, callback=print_bench_version, expose_value=False)
 def bench_command(bench_path='.'):
 	import bench
-	from bench.utils import setup_logging
-
 	bench.set_frappe_version(bench_path=bench_path)
-	setup_logging(bench_path=bench_path)
 
 
 from bench.commands.make import init, get_app, new_app, remove_app, exclude_app_for_update, include_app_for_update, pip

bench/utils.py

@@ -39,7 +39,7 @@ class PatchError(Exception):
 class CommandFailedError(Exception):
 	pass
 
-logger = logging.getLogger(__name__)
+logger = logging.getLogger(bench.PROJECT_NAME)
 bench_cache_file = '.bench.cmd'
 folders_in_bench = ('apps', 'sites', 'config', 'logs', 'config/pids')
 sudoers_file = '/etc/sudoers.d/frappe'
@@ -139,7 +139,7 @@ def init(path, apps_path=None, no_procfile=False, no_backups=False,
 			if e.errno == errno.EEXIST:
 				pass
 
-	setup_logging()
+	setup_logging(bench_path=path)
 
 	setup_env(bench_path=path, python=python)
 
@@ -297,8 +297,13 @@ def clone_apps_from(bench_path, clone_from, update_app=True):
 def exec_cmd(cmd, cwd='.'):
 	import shlex
 	print("{0}$ {1}{2}".format(color.silver, cmd, color.nc))
+	cwd_info = "cd {0} && ".format(cwd) if cwd != "." else ""
+	cmd_log = "{0}{1}".format(cwd_info, cmd)
+	logger.debug(cmd_log)
 	cmd = shlex.split(cmd)
-	return subprocess.call(cmd, cwd=cwd, universal_newlines=True)
+	return_code = subprocess.call(cmd, cwd=cwd, universal_newlines=True)
+	if return_code:
+		logger.warn("{0} executed with exit code {1}".format(cmd_log, return_code))
 
 
 def which(executable, raise_err = False):
@@ -372,7 +377,7 @@ def get_sites(bench_path='.'):
 
 def setup_backups(bench_path='.'):
 	from bench.config.common_site_config import get_config
-	logger.info('setting up backups')
+	logger.log('setting up backups')
 
 	bench_dir = os.path.abspath(bench_path)
 	user = get_config(bench_path=bench_dir).get('frappe_user')
@@ -424,15 +429,37 @@ def setup_sudoers(user):
 
 
 def setup_logging(bench_path='.'):
+	LOG_LEVEL = 15
+	logging.addLevelName(LOG_LEVEL, "LOG")
+	def logv(self, message, *args, **kws):
+		if self.isEnabledFor(LOG_LEVEL):
+			self._log(LOG_LEVEL, message, args, **kws)
+	logging.Logger.log = logv
+
+	class log_filter(object):
+		def __init__(self, level):
+			self.__level = level
+
+		def filter(self, logRecord):
+			return logRecord.levelno == self.__level
+
 	if os.path.exists(os.path.join(bench_path, 'logs')):
 		logger = logging.getLogger(bench.PROJECT_NAME)
 		log_file = os.path.join(bench_path, 'logs', 'bench.log')
 		formatter = logging.Formatter('%(asctime)s %(levelname)s %(message)s')
 		hdlr = logging.FileHandler(log_file)
 		hdlr.setFormatter(formatter)
+
+		log_hndlr = logging.StreamHandler(sys.stdout)
+		log_hndlr.setFormatter(logging.Formatter('%(message)s'))
+		log_hndlr.addFilter(log_filter(LOG_LEVEL))
+
 		logger.addHandler(hdlr)
+		logger.addHandler(log_hndlr)
 		logger.setLevel(logging.DEBUG)
 
+		return logger
+
 
 def get_process_manager():
 	for proc_man in ['honcho', 'foreman', 'forego']:
@@ -1070,9 +1097,9 @@ def migrate_env(python, backup=False):
 
 		redis  = '{redis} -p {port}'.format(redis=which('redis-cli'), port=rredis.port)
 
-		logger.debug('Clearing Redis Cache...')
+		logger.log('Clearing Redis Cache...')
 		exec_cmd('{redis} FLUSHALL'.format(redis = redis))
-		logger.debug('Clearing Redis DataBase...')
+		logger.log('Clearing Redis DataBase...')
 		exec_cmd('{redis} FLUSHDB'.format(redis = redis))
 	except:
 		logger.warn('Please ensure Redis Connections are running or Daemonized.')
@@ -1086,7 +1113,7 @@ def migrate_env(python, backup=False):
 		source = os.path.join(path, 'env')
 		target = parch
 
-		logger.debug('Backing up Virtual Environment')
+		logger.log('Backing up Virtual Environment')
 		stamp = datetime.now().strftime('%Y%m%d_%H%M%S')
 		dest = os.path.join(path, str(stamp))
 
@@ -1094,17 +1121,18 @@ def migrate_env(python, backup=False):
 		shutil.move(dest, target)
 
 	# Create virtualenv using specified python
+	venv_creation, packages_setup = 1, 1
 	try:
-		logger.debug('Setting up a New Virtual {} Environment'.format(python))
+		logger.log('Setting up a New Virtual {} Environment'.format(python))
-		exec_cmd('{virtualenv} --python {python} {pvenv}'.format(virtualenv=virtualenv, python=python, pvenv=pvenv))
+		venv_creation = exec_cmd('{virtualenv} --python {python} {pvenv}'.format(virtualenv=virtualenv, python=python, pvenv=pvenv))
 
 		apps = ' '.join(["-e {}".format(os.path.join("apps", app)) for app in get_apps()])
-		exec_cmd('{0} install -q -U {1}'.format(pip, apps))
+		packages_setup = exec_cmd('{0} install -q -U {1}'.format(pip, apps))
 
-		logger.debug('Migration Successful to {}'.format(python))
+		logger.log('Migration Successful to {}'.format(python))
 	except:
-		logger.debug('Migration Error')
+		if venv_creation or packages_setup:
-		raise
+			logger.warn('Migration Error')
 
 
 def is_dist_editable(dist):