fix: cleaner and intuitive bench logs

bench/app.py

@@ -23,8 +23,7 @@
 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(__name__)
+logger = logging.getLogger(bench.PROJECT_NAME)
 
 
 class InvalidBranchException(Exception): pass
@@ -135,7 +134,7 @@ def get_app(git_url, branch=None, bench_path='.', skip_assets=False, verbose=Fal
 			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,
@@ -160,7 +159,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)
 
@@ -173,7 +172,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 ""
@@ -267,7 +266,7 @@ def pull_apps(apps=None, bench_path='.', reset=False):
 				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,18 +14,20 @@
 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"
 
 
 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 setup_app(app):
 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,6 +429,13 @@ 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
+
 	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')
@@ -433,6 +445,8 @@ def setup_logging(bench_path='.'):
 		logger.addHandler(hdlr)
 		logger.setLevel(logging.DEBUG)
 
+		return logger
+
 
 def get_process_manager():
 	for proc_man in ['honcho', 'foreman', 'forego']:
@@ -1070,9 +1084,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,25 +1100,26 @@ 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))
 
 		os.rename(source, dest)
 		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))
-		exec_cmd('{virtualenv} --python {python} {pvenv}'.format(virtualenv=virtualenv, python=python, pvenv=pvenv))
+		logger.log('Setting up a New Virtual {} Environment'.format(python))
+		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')
-		raise
+		if venv_creation or packages_setup:
+			logger.warn('Migration Error')
 
 
 def is_dist_editable(dist):