From 0be833ad850e5d68fefd906bb3e0607127849d4b Mon Sep 17 00:00:00 2001 From: Gavin D'souza Date: Tue, 19 May 2020 13:11:57 +0530 Subject: [PATCH 1/2] fix: cleaner and intuitive bench logs --- bench/app.py | 11 +++++----- bench/cli.py | 9 ++++++--- bench/commands/__init__.py | 3 --- bench/utils.py | 41 ++++++++++++++++++++++++++------------ 4 files changed, 39 insertions(+), 25 deletions(-) diff --git a/bench/app.py b/bench/app.py index 8b165b2b..de7f8c4e 100755 --- a/bench/app.py +++ b/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(__name__) +logger = logging.getLogger(bench.PROJECT_NAME) class InvalidBranchException(Exception): pass @@ -135,7 +134,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, @@ -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 @@ 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( diff --git a/bench/cli.py b/bench/cli.py index 09c001d8..0cc53310 100755 --- a/bench/cli.py +++ b/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) diff --git a/bench/commands/__init__.py b/bench/commands/__init__.py index 8ee317d9..2b073b65 100755 --- a/bench/commands/__init__.py +++ b/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 diff --git a/bench/utils.py b/bench/utils.py index 67ff3364..9bd65ad3 100755 --- a/bench/utils.py +++ b/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,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,7 +1100,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 +1108,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)) - 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): From 53919b624e17e108006d66bddb0981658aeefaf0 Mon Sep 17 00:00:00 2001 From: Gavin D'souza Date: Tue, 19 May 2020 13:47:48 +0530 Subject: [PATCH 2/2] fix: add log filter to handler --- bench/app.py | 8 ++++---- bench/utils.py | 13 +++++++++++++ 2 files changed, 17 insertions(+), 4 deletions(-) diff --git a/bench/app.py b/bench/app.py index de7f8c4e..4beaf988 100755 --- a/bench/app.py +++ b/bench/app.py @@ -134,7 +134,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.log( '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, @@ -159,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.log( '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) @@ -172,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.log( "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 "" @@ -266,7 +266,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.log( '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( diff --git a/bench/utils.py b/bench/utils.py index 9bd65ad3..2e6b31fa 100755 --- a/bench/utils.py +++ b/bench/utils.py @@ -436,13 +436,26 @@ def setup_logging(bench_path='.'): 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