From d6b3a9e0c0b700f65905942e49fd50673c176990 Mon Sep 17 00:00:00 2001 From: Jonathan Kidner <12627199+Zoophobus@users.noreply.github.com> Date: Mon, 28 Aug 2023 11:00:07 +0200 Subject: [PATCH] Updates to the python logging system for the AB (#1011) * Updates to the logging system to avoid the print statement. Improves thread safety in logging increasing stability in the multi-threaded processes. * Changes the creation of log files. Adds the .logs to .gitignore. * Simplifies the use of the python logging facility with QtThreads (as published on the python docs for logging), improving the stability of logging. * Changes the generation of the logging object that is more compatible with pytest, supporting the existing test procedures. * The ABHandler module contains the formats and settings for the Stream handlers. Calling of the methods in the other AB modules requires passing a logging.Logger instance and the name of the calling module. * An error wrapper is provided and also explicitly provides a trace of the error. * A timestamp routine is provided and used for providing the file names for log files. * A standard location based on appdirs is provided and logged to the consoles (and log file). * Formatting of the console streams is changed to provide a simpler, easier to read structure avoiding the time and location stamps. --- .gitignore | 4 +- activity_browser/__init__.py | 12 +- activity_browser/bwutils/calculations.py | 10 +- activity_browser/bwutils/commontasks.py | 18 +- activity_browser/bwutils/metadata.py | 19 +- activity_browser/bwutils/montecarlo.py | 24 ++- activity_browser/bwutils/multilca.py | 8 +- activity_browser/bwutils/pedigree.py | 1 - .../bwutils/sensitivity_analysis.py | 39 ++-- activity_browser/bwutils/strategies.py | 17 +- .../bwutils/superstructure/excel.py | 8 +- .../bwutils/superstructure/file_imports.py | 14 +- .../bwutils/superstructure/manager.py | 11 +- .../bwutils/superstructure/utils.py | 8 +- activity_browser/controllers/database.py | 10 +- activity_browser/controllers/plugin.py | 21 ++- activity_browser/controllers/project.py | 40 ++-- activity_browser/layouts/panels/panel.py | 16 +- activity_browser/layouts/panels/right.py | 10 +- .../layouts/tabs/LCA_results_tab.py | 8 +- .../layouts/tabs/LCA_results_tabs.py | 28 ++- activity_browser/layouts/tabs/LCA_setup.py | 14 +- activity_browser/layouts/tabs/debug.py | 16 +- .../layouts/tabs/impact_categories.py | 1 - activity_browser/logger.py | 173 ++++++++++++++++++ activity_browser/settings.py | 8 +- activity_browser/signals.py | 1 + activity_browser/ui/figures.py | 8 +- activity_browser/ui/statusbar.py | 7 +- activity_browser/ui/tables/LCA_setup.py | 8 +- activity_browser/ui/tables/models/activity.py | 15 +- activity_browser/ui/tables/models/base.py | 14 +- .../ui/tables/models/impact_categories.py | 9 +- .../ui/tables/models/inventory.py | 8 +- .../ui/tables/models/lca_setup.py | 37 +++- .../ui/tables/models/parameters.py | 10 +- activity_browser/ui/tables/views.py | 8 +- activity_browser/ui/web/base.py | 8 +- activity_browser/ui/web/navigator.py | 26 ++- activity_browser/ui/web/sankey_navigator.py | 12 +- activity_browser/ui/web/webutils.py | 1 - .../ui/widgets/biosphere_update.py | 8 +- .../ui/wizards/db_import_wizard.py | 19 +- .../ui/wizards/settings_wizard.py | 14 +- activity_browser/ui/wizards/uncertainty.py | 8 +- pytest.ini | 1 + run-activity-browser.py | 8 + tests/pytest.ini | 4 + tests/test_uncertainty_wizard.py | 17 +- 49 files changed, 615 insertions(+), 174 deletions(-) create mode 100644 activity_browser/logger.py create mode 100644 tests/pytest.ini diff --git a/.gitignore b/.gitignore index 95ca89299..452f2cd84 100644 --- a/.gitignore +++ b/.gitignore @@ -16,4 +16,6 @@ activity_browser/ABSettings.json *.bak /.idea /.vscode -.coverage \ No newline at end of file +.coverage +.logs +test/.logs diff --git a/activity_browser/__init__.py b/activity_browser/__init__.py index 643ce3879..5641d521b 100644 --- a/activity_browser/__init__.py +++ b/activity_browser/__init__.py @@ -9,7 +9,11 @@ from .application import Application from .info import __version__ from .plugin import Plugin +import logging +from .logger import ABHandler +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) # https://bugreports.qt.io/browse/QTBUG-87014 # https://bugreports.qt.io/browse/QTBUG-85546 @@ -20,11 +24,11 @@ if QSysInfo.productVersion() not in supported: os.environ["QT_MAC_WANTS_LAYER"] = "1" os.environ["QTWEBENGINE_CHROMIUM_FLAGS"] = "--disable-gpu" - print("Info: GPU hardware acceleration disabled") + log.info("Info: GPU hardware acceleration disabled") if QSysInfo.productType() in ["arch","nixos"]: os.environ["QTWEBENGINE_CHROMIUM_FLAGS"] = "--no-sandbox" - print("Info: QtWebEngine sandbox disabled") + log.info("Info: QtWebEngine sandbox disabled") def run_activity_browser(): qapp = QApplication(sys.argv) @@ -39,10 +43,10 @@ def run_activity_browser(): # ) application = Application() application.show() - print("Qt Version:", qt_version) + log.info("Qt Version:", qt_version) def exception_hook(*args): - print(''.join(traceback.format_exception(*args))) + log.warning(''.join(traceback.format_exception(*args))) sys.excepthook = exception_hook diff --git a/activity_browser/bwutils/calculations.py b/activity_browser/bwutils/calculations.py index fd3b3b0f3..8557815c3 100644 --- a/activity_browser/bwutils/calculations.py +++ b/activity_browser/bwutils/calculations.py @@ -6,9 +6,13 @@ SuperstructureContributions, SuperstructureMLCA, ) from bw2calc.errors import BW2CalcError -import brightway2 as bw -from .errors import ReferenceFlowValueError +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + def do_LCA_calculations(data: dict): """Perform the MLCA calculation.""" @@ -39,7 +43,7 @@ def do_LCA_calculations(data: dict): except KeyError as e: raise BW2CalcError("LCA Failed", str(e)).with_traceback(e.__traceback__) else: - print('Calculation type must be: simple or scenario. Given:', cs_name) + log.error('Calculation type must be: simple or scenario. Given:', cs_name) raise ValueError mlca.calculate() diff --git a/activity_browser/bwutils/commontasks.py b/activity_browser/bwutils/commontasks.py index 28360de93..4c4b395fb 100644 --- a/activity_browser/bwutils/commontasks.py +++ b/activity_browser/bwutils/commontasks.py @@ -9,6 +9,12 @@ from bw2data.proxies import ActivityProxyBase from bw2data.project import ProjectDataset, SubstitutableDatabase +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + """ bwutils is a collection of methods that build upon brightway2 and are generic enough to provide here so that we avoid re-typing the same code in different parts of the Activity Browser. @@ -65,7 +71,7 @@ def format_activity_label(key, style='pnl', max_length=40): def switch_brightway2_dir(dirpath): bw_base = bw.projects._base_data_dir if dirpath == bw_base: - print('dirpath already loaded') + log.info('dirpath already loaded') return False try: assert os.path.isdir(dirpath) @@ -79,10 +85,10 @@ def switch_brightway2_dir(dirpath): os.path.join(bw.projects._base_data_dir, "projects.db"), [ProjectDataset] ) - print('Loaded brightway2 data directory: {}'.format(bw.projects._base_data_dir)) + log.info('Loaded brightway2 data directory: {}'.format(bw.projects._base_data_dir)) return True except AssertionError: - print('Could not access BW_DIR as specified in settings.py') + log.error('Could not access BW_DIR as specified in settings.py') return False @@ -92,7 +98,7 @@ def cleanup_deleted_bw_projects() -> None: NOTE: This cannot be done from within the AB. """ n_dir = bw.projects.purge_deleted_directories() - print('Deleted {} unused project directories!'.format(n_dir)) + log.info('Deleted {} unused project directories!'.format(n_dir)) # Database @@ -136,7 +142,7 @@ def count_database_records(name: str) -> int: try: return len(db) except TypeError as e: - print("{}. Counting manually".format(e)) + log.error("{}. Counting manually".format(e)) return sum(1 for _ in db) @@ -250,7 +256,7 @@ def get_exchanges_in_scenario_difference_file_notation(exchanges): except: # The input activity does not exist. remove the exchange. - print("Something did not work with the following exchange: {}. It was removed from the list.".format(exc)) + log.error("Something did not work with the following exchange: {}. It was removed from the list.".format(exc)) return data diff --git a/activity_browser/bwutils/metadata.py b/activity_browser/bwutils/metadata.py index 389cd39c0..f909d53d9 100644 --- a/activity_browser/bwutils/metadata.py +++ b/activity_browser/bwutils/metadata.py @@ -7,6 +7,11 @@ from .commontasks import count_database_records +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) # todo: extend store over several projects @@ -61,12 +66,12 @@ def add_metadata(self, db_names_list: list) -> None: dfs = list() dfs.append(self.dataframe) - print('Current shape and databases in the MetaDataStore:', self.dataframe.shape, self.databases) + log.info('Current shape and databases in the MetaDataStore:', self.dataframe.shape, self.databases) for db_name in new: if db_name not in bw.databases: raise ValueError('This database does not exist:', db_name) - print('Adding:', db_name) + log.info('Adding:', db_name) self.databases.add(db_name) # make a temporary DataFrame and index it by ('database', 'code') (like all brightway activities) @@ -113,7 +118,7 @@ def update_metadata(self, key: tuple) -> None: act = bw.get_activity(key) # if this does not work, it has been deleted (see except:). except (UnknownObject, ActivityDataset.DoesNotExist): # Situation 1: activity has been deleted (metadata needs to be deleted) - print('Deleting activity from metadata:', key) + log.warning('Deleting activity from metadata:', key) self.dataframe.drop(key, inplace=True) # print('Dimensions of the Metadata:', self.dataframe.shape) return @@ -124,13 +129,13 @@ def update_metadata(self, key: tuple) -> None: self.add_metadata([db]) else: if key in self.dataframe.index: # Situation 2: activity has been modified (metadata needs to be updated) - print('Updating activity in metadata: ', act, key) + log.info('Updating activity in metadata: ', act, key) for col in self.dataframe.columns: self.dataframe.at[key, col] = act.get(col, '') self.dataframe.at[key, 'key'] = act.key else: # Situation 3: Activity has been added to database (metadata needs to be generated) - print('Adding activity to metadata:', act, key) + log.info('Adding activity to metadata:', act, key) df_new = pd.DataFrame([act.as_dict()], index=pd.MultiIndex.from_tuples([act.key])) df_new['key'] = [act.key] self.dataframe = pd.concat([self.dataframe, df_new], sort=False) @@ -140,7 +145,7 @@ def update_metadata(self, key: tuple) -> None: def reset_metadata(self) -> None: """Deletes metadata when the project is changed.""" # todo: metadata could be collected across projects... - print('Reset metadata.') + log.info('Reset metadata.') self.dataframe = pd.DataFrame() self.databases = set() @@ -210,7 +215,7 @@ def get_units(self, db_name: str) -> set: def print_convenience_information(self, db_name: str) -> None: """ Reports how many unique locations and units the database has. """ - print("{} unique locations and {} unique units in {}".format( + log.info("{} unique locations and {} unique units in {}".format( len(self.get_locations(db_name)), len(self.get_units(db_name)), db_name )) diff --git a/activity_browser/bwutils/montecarlo.py b/activity_browser/bwutils/montecarlo.py index a741f0c00..67314eeda 100644 --- a/activity_browser/bwutils/montecarlo.py +++ b/activity_browser/bwutils/montecarlo.py @@ -11,6 +11,12 @@ from .manager import MonteCarloParameterManager +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class MonteCarloLCA(object): """A Monte Carlo LCA for multiple reference flows and methods loaded from a calculation setup.""" @@ -228,7 +234,7 @@ def calculate(self, iterations=10, seed: int = None, **kwargs): self.lca.lcia_calculation() self.results[iteration, row, col] = self.lca.score - print('Monte Carlo LCA: finished {} iterations for {} reference flows and {} methods in {} seconds.'.format( + log.info('Monte Carlo LCA: finished {} iterations for {} reference flows and {} methods in {} seconds.'.format( iterations, len(self.func_units), len(self.methods), @@ -254,10 +260,10 @@ def get_results_by(self, act_key=None, method=None): if act_key: act_index = self.activity_index.get(act_key) - print('Activity key provided:', act_key, act_index) + log.info('Activity key provided:', act_key, act_index) if method: method_index = self.method_index.get(method) - print('Method provided', method, method_index) + log.info('Method provided', method, method_index) if not act_key and not method: return self.results @@ -266,7 +272,7 @@ def get_results_by(self, act_key=None, method=None): elif method and not act_key: return np.squeeze(self.results[:, :, method_index]) elif method and act_key: - print(act_index, method_index) + log.info(act_index, method_index) return np.squeeze(self.results[:, act_index, method_index]) def get_results_dataframe(self, act_key=None, method=None, labelled=True): @@ -317,7 +323,7 @@ def get_labels(key_list, fields: list = None, separator=' | ', def perform_MonteCarlo_LCA(project='default', cs_name=None, iterations=10): """Performs Monte Carlo LCA based on a calculation setup and returns the Monte Carlo LCA object.""" - print('-- Monte Carlo LCA --\n Project:', project, 'CS:', cs_name) + log.info('-- Monte Carlo LCA --\n Project:', project, 'CS:', cs_name) bw.projects.set_current(project) # perform Monte Carlo simulation @@ -330,14 +336,14 @@ def perform_MonteCarlo_LCA(project='default', cs_name=None, iterations=10): mc = perform_MonteCarlo_LCA(project='ei34', cs_name='kraft paper', iterations=15) # test the get_results_by() method - print('\nTesting the get_results_by() method') +# print('\nTesting the get_results_by() method') act_key = mc.activity_keys[0] method = mc.methods[0] - print(mc.get_results_by(act_key=act_key, method=method)) +# print(mc.get_results_by(act_key=act_key, method=method)) # print(mc.get_results_by(act_key=act_key, method=None)) # print(mc.get_results_by(act_key=None, method=method)) # print(mc.get_results_by(act_key=None, method=None)) # testing the dataframe output - print(mc.get_results_dataframe(method=mc.methods[0])) - print(mc.get_results_dataframe(act_key=mc.activity_keys[0])) \ No newline at end of file +# print(mc.get_results_dataframe(method=mc.methods[0])) +# print(mc.get_results_dataframe(act_key=mc.activity_keys[0])) \ No newline at end of file diff --git a/activity_browser/bwutils/multilca.py b/activity_browser/bwutils/multilca.py index 6db306332..c57e45f58 100644 --- a/activity_browser/bwutils/multilca.py +++ b/activity_browser/bwutils/multilca.py @@ -12,6 +12,12 @@ from .metadata import AB_metadata from .errors import ReferenceFlowValueError +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class MLCA(object): """Wrapper class for performing LCA calculations with many reference flows and impact categories. @@ -487,7 +493,7 @@ def join_df_with_metadata(cls, df, x_fields=None, y_fields=None, complete_index = special_keys + keys joined = joined.reindex(complete_index, axis="index", fill_value=0.) except: - print('Could not put Total and Rest on positions 0 and 1 in the dataframe.') + log.error('Could not put Total and Rest on positions 0 and 1 in the dataframe.') joined.index = cls.get_labels(joined.index, fields=x_fields) return joined diff --git a/activity_browser/bwutils/pedigree.py b/activity_browser/bwutils/pedigree.py index 2d5146a60..1a1e7b863 100644 --- a/activity_browser/bwutils/pedigree.py +++ b/activity_browser/bwutils/pedigree.py @@ -13,7 +13,6 @@ smoothly into the related uncertainty distributions. """ import math -from pprint import pformat from bw2data.parameters import ParameterBase from bw2data.proxies import ExchangeProxyBase diff --git a/activity_browser/bwutils/sensitivity_analysis.py b/activity_browser/bwutils/sensitivity_analysis.py index 50de03f19..ac70e5d23 100644 --- a/activity_browser/bwutils/sensitivity_analysis.py +++ b/activity_browser/bwutils/sensitivity_analysis.py @@ -17,13 +17,19 @@ from .montecarlo import MonteCarloLCA, perform_MonteCarlo_LCA from ..settings import ab_settings +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + def get_lca(fu, method): """Calculates a non-stochastic LCA and returns a the LCA object.""" lca = bw.LCA(fu, method=method) lca.lci() lca.lcia() - print('Non-stochastic LCA score:', lca.score) + log.info('Non-stochastic LCA score:', lca.score) # add reverse dictionaries lca.activity_dict_rev, lca.product_dict_rev, lca.biosphere_dict_rev = lca.reverse_dict() @@ -42,7 +48,7 @@ def filter_technosphere_exchanges(fu, method, cutoff=0.05, max_calc=1e4): for e in res['edges']: if e['to'] != -1: # filter out head introduced in graph traversal technosphere_exchange_indices.append((e['from'], e['to'])) - print('TECHNOSPHERE {} filtering resulted in {} of {} exchanges and took {} iterations in {} seconds.'.format( + log.info('TECHNOSPHERE {} filtering resulted in {} of {} exchanges and took {} iterations in {} seconds.'.format( res['lca'].technosphere_matrix.shape, len(technosphere_exchange_indices), res['lca'].technosphere_matrix.getnnz(), @@ -57,16 +63,11 @@ def filter_biosphere_exchanges(lca, cutoff=0.005): category in a non-stochastic LCA.""" start = time() - # print('LCA score:', lca.score) inv = lca.characterized_inventory - # print('Characterized inventory:', inv.shape, inv.nnz) finv = inv.multiply(abs(inv) > abs(lca.score/(1/cutoff))) - # print('Filtered characterized inventory:', finv.shape, finv.nnz) biosphere_exchange_indices = list(zip(*finv.nonzero())) - # print(biosphere_indices[:2]) explained_fraction = finv.sum() / lca.score - # print('Explained fraction of LCA score:', explained_fraction) - print('BIOSPHERE {} filtering resulted in {} of {} exchanges ({}% of total impact) and took {} seconds.'.format( + log.info('BIOSPHERE {} filtering resulted in {} of {} exchanges ({}% of total impact) and took {} seconds.'.format( inv.shape, finv.nnz, inv.nnz, @@ -122,7 +123,7 @@ def drop_no_uncertainty_exchanges(excs, indices): if exc.get('uncertainty type') and exc.get('uncertainty type') >= 1: excs_no.append(exc) indices_no.append(ind) - print('Dropping {} exchanges of {} with no uncertainty. {} remaining.'.format( + log.info('Dropping {} exchanges of {} with no uncertainty. {} remaining.'.format( len(excs) - len(excs_no), len(excs), len(excs_no) )) return excs_no, indices_no @@ -192,7 +193,7 @@ def get_CF_dataframe(lca, only_uncertain_CFs=True): data[params_index]['index'] = cf_index data[params_index]['GSA name'] = "CF: " + bio_act['name'] + str(bio_act['categories']) - print('CHARACTERIZATION FACTORS filtering resulted in including {} of {} characteriation factors.'.format( + log.info('CHARACTERIZATION FACTORS filtering resulted in including {} of {} characteriation factors.'.format( len(data), len(lca.cf_params), )) @@ -206,10 +207,10 @@ def get_parameters_DF(mc): if bool(mc.parameter_data): # returns False if dict is empty dfp = pd.DataFrame(mc.parameter_data).T dfp['GSA name'] = "P: " + dfp['name'] - print('PARAMETERS:', len(dfp)) + log.info('PARAMETERS:', len(dfp)) return dfp else: - print('PARAMETERS: None included.') + log.info('PARAMETERS: None included.') return pd.DataFrame() # return emtpy df @@ -299,10 +300,10 @@ def perform_GSA(self, act_number=0, method_number=0, except Exception as e: traceback.print_exc() # todo: QMessageBox.warning(self, 'Could not perform Delta analysis', str(e)) - print('Initializing the GSA failed.') + log.error('Initializing the GSA failed.') return None - print('-- GSA --\n Project:', bw.projects.current, 'CS:', self.mc.cs_name, + log.info('-- GSA --\n Project:', bw.projects.current, 'CS:', self.mc.cs_name, 'Activity:', self.activity, 'Method:', self.method) # get non-stochastic LCA object with reverse dictionaries @@ -378,12 +379,12 @@ def perform_GSA(self, act_number=0, method_number=0, # self.Y = np.log(np.abs(self.Y)) # this makes it more robust for very uneven distributions of LCA results if np.all(self.Y > 0): # all positive numbers self.Y = np.log(np.abs(self.Y)) - print('All positive LCA scores. Log-transformation performed.') + log.info('All positive LCA scores. Log-transformation performed.') elif np.all(self.Y < 0): # all negative numbers self.Y = -np.log(np.abs(self.Y)) - print('All negative LCA scores. Log-transformation performed.') + log.info('All negative LCA scores. Log-transformation performed.') else: # mixed positive and negative numbers - print('Log-transformation cannot be applied as LCA scores overlap zero.') + log.warning('Log-transformation cannot be applied as LCA scores overlap zero.') # print('Filtering took {} seconds'.format(np.round(time() - start, 2))) @@ -395,7 +396,7 @@ def perform_GSA(self, act_number=0, method_number=0, # perform delta analysis time_delta = time() self.Si = delta.analyze(self.problem, self.X, self.Y, print_to_console=False) - print('Delta analysis took {} seconds'.format(np.round(time() - time_delta, 2), )) + log.info('Delta analysis took {} seconds'.format(np.round(time() - time_delta, 2), )) # put GSA results in to dataframe self.dfgsa = pd.DataFrame(self.Si, index=self.names).sort_values(by='delta', ascending=False) @@ -406,7 +407,7 @@ def perform_GSA(self, act_number=0, method_number=0, self.df_final.reset_index(inplace=True) self.df_final['pedigree'] = [str(x) for x in self.df_final['pedigree']] - print('GSA took {} seconds'.format(np.round(time() - start, 2))) + log.info('GSA took {} seconds'.format(np.round(time() - start, 2))) def get_save_name(self): save_name = self.mc.cs_name + '_' + str(self.mc.iterations) + '_' + self.activity['name'] + \ diff --git a/activity_browser/bwutils/strategies.py b/activity_browser/bwutils/strategies.py index dc014a4c8..690ff9ae9 100644 --- a/activity_browser/bwutils/strategies.py +++ b/activity_browser/bwutils/strategies.py @@ -11,6 +11,13 @@ from .commontasks import clean_activity_name from ..bwutils.errors import ExchangeErrorValues + +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + TECHNOSPHERE_TYPES = {"technosphere", "substitution", "production"} BIOSPHERE_TYPES = {"economic", "emission", "natural resource", "social"} @@ -118,7 +125,7 @@ def relink_exchanges(exchanges: list, candidates: dict, duplicates: dict) -> tup # Commit changes every 10k exchanges. transaction.commit() except (StrategyError, ValidityError) as e: - print(e) + log.error(e) transaction.rollback() return (remainder, altered, unlinked_exchanges) @@ -129,7 +136,7 @@ def relink_exchanges_existing_db(db: bw.Database, old: str, other: bw.Database) This means possibly doing a lot of sqlite update calls. """ if old == other.name: - print("No point relinking to same database.") + log.info("No point relinking to same database.") return assert db.backend == "sqlite", "Relinking only allowed for SQLITE backends" assert other.backend == "sqlite", "Relinking only allowed for SQLITE backends" @@ -150,7 +157,7 @@ def relink_exchanges_existing_db(db: bw.Database, old: str, other: bw.Database) # this updates the 'depends' in metadata (remainder, altered, unlinked_exchanges) = relink_exchanges(exchanges, candidates, duplicates) db.process() - print( + log.info( "Relinked database '{}', {} exchange inputs changed from '{}' to '{}'.".format( db.name, altered, old, other.name ) @@ -160,7 +167,7 @@ def relink_exchanges_existing_db(db: bw.Database, old: str, other: bw.Database) def relink_activity_exchanges(act, old: str, other: bw.Database) -> tuple: if old == other.name: - print("No point relinking to same database.") + log.info("No point relinking to same database.") return db = bw.Database(act.key[0]) assert db.backend == "sqlite", "Relinking only allowed for SQLITE backends" @@ -179,7 +186,7 @@ def relink_activity_exchanges(act, old: str, other: bw.Database) -> tuple: (remainder, altered, unlinked_exchanges) = relink_exchanges(exchanges, candidates, duplicates) db.process() - print( + log.info( "Relinked database '{}', {} exchange inputs changed from '{}' to '{}'.".format( db.name, altered, old, other.name ) diff --git a/activity_browser/bwutils/superstructure/excel.py b/activity_browser/bwutils/superstructure/excel.py index cc7f64524..be98fe1d6 100644 --- a/activity_browser/bwutils/superstructure/excel.py +++ b/activity_browser/bwutils/superstructure/excel.py @@ -8,6 +8,12 @@ from .utils import SUPERSTRUCTURE +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + def convert_tuple_str(x): try: @@ -21,7 +27,7 @@ def get_sheet_names(document_path: Union[str, Path]) -> List[str]: wb = openpyxl.load_workbook(filename=document_path, read_only=True) return wb.sheetnames except UnicodeDecodeError as e: - print("Given document uses an unknown encoding: {}".format(e)) + log.error("Given document uses an unknown encoding: {}".format(e)) def get_header_index(document_path: Union[str, Path], import_sheet: int): """Retrieves the line index for the column headers, will raise an diff --git a/activity_browser/bwutils/superstructure/file_imports.py b/activity_browser/bwutils/superstructure/file_imports.py index af88491db..00d9d7375 100644 --- a/activity_browser/bwutils/superstructure/file_imports.py +++ b/activity_browser/bwutils/superstructure/file_imports.py @@ -6,10 +6,16 @@ from typing import Optional, Union from ..errors import ( - ImportCanceledError, ActivityProductionValueError, IncompatibleDatabaseNamingError, + ActivityProductionValueError, IncompatibleDatabaseNamingError, InvalidSDFEntryValue, ExchangeErrorValues ) +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class ABPopup(QMessageBox): """ @@ -142,7 +148,7 @@ def database_and_key_check(data: pd.DataFrame) -> None: msg = "Error in importing file with activity {} and {}".format(ds[4], ds[5]) raise IncompatibleDatabaseNamingError() except IncompatibleDatabaseNamingError as e: - print(msg) + log.error(msg) raise e @staticmethod @@ -160,7 +166,7 @@ def production_process_check(data: pd.DataFrame, scenario_names: list) -> None: msg = "Error with the production value in the exchange between activity {} and {}".format(failed['from activity name'], failed['to activity name']) raise ActivityProductionValueError() except ActivityProductionValueError as e: - print(msg) + log.error(msg) raise e @staticmethod @@ -179,7 +185,7 @@ def na_value_check(data: pd.DataFrame, fields: list) -> None: msg = "Error with NA's in the exchange between activity {} and {}".format(hasNA['from activity name'], hasNA['to activity name']) raise InvalidSDFEntryValue() except InvalidSDFEntryValue as e: - print(msg) + log.error(msg) raise e @staticmethod diff --git a/activity_browser/bwutils/superstructure/manager.py b/activity_browser/bwutils/superstructure/manager.py index 60f0793fb..7b23417d2 100644 --- a/activity_browser/bwutils/superstructure/manager.py +++ b/activity_browser/bwutils/superstructure/manager.py @@ -11,6 +11,12 @@ from .dataframe import scenario_columns from .utils import guess_flow_type, SUPERSTRUCTURE, _time_it_ +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + EXCHANGE_KEYS = pd.Index(["from key", "to key"]) INDEX_KEYS = pd.Index(["from key", "to key", "flow type"]) @@ -163,7 +169,6 @@ def merge_flows_to_self(df: pd.DataFrame) -> pd.DataFrame: extra_df = pd.DataFrame(list_exc) extra_df.index = prod_idxs - extra_df.loc[:, scenario_cols] = extra_df.loc[:, scenario_cols] / (extra_df.loc[:, scenario_cols] + df.loc[tech_idxs, scenario_cols].values) # drop the 'technosphere' flows @@ -179,7 +184,7 @@ def remove_duplicates(df: pd.DataFrame) -> pd.DataFrame: """ duplicates = df.index.duplicated(keep="last") if duplicates.any(): - print("Found and dropped {} duplicate exchanges.".format(duplicates.sum())) + log.warning("Found and dropped {} duplicate exchanges.".format(duplicates.sum())) return df.loc[~duplicates, :] return df @@ -198,7 +203,7 @@ def build_index(df: pd.DataFrame) -> pd.MultiIndex: len(df)) unknown_flows = df.loc[:, "flow type"].isna() if unknown_flows.any(): - print("Not all flow types are known, guessing {} flows".format( + log.warning("Not all flow types are known, guessing {} flows".format( unknown_flows.sum() )) df.loc[unknown_flows, "flow type"] = df.loc[ diff --git a/activity_browser/bwutils/superstructure/utils.py b/activity_browser/bwutils/superstructure/utils.py index 27823e48e..77cec5538 100644 --- a/activity_browser/bwutils/superstructure/utils.py +++ b/activity_browser/bwutils/superstructure/utils.py @@ -3,6 +3,12 @@ import pandas as pd import time +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + # Different kinds of indexes, to allow for quick selection of data from # the Superstructure DataFrame. SUPERSTRUCTURE = pd.Index([ @@ -39,6 +45,6 @@ def _time_it_(func): def wrapper(*args): now = time.time() result = func(*args) - print(f"{func} -- " + str(time.time() - now)) + log.info(f"{func} -- " + str(time.time() - now)) return result return wrapper \ No newline at end of file diff --git a/activity_browser/controllers/database.py b/activity_browser/controllers/database.py index 38f88f71e..1e3068676 100644 --- a/activity_browser/controllers/database.py +++ b/activity_browser/controllers/database.py @@ -17,8 +17,16 @@ from ..signals import signals from .project import ProjectController +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + + class DatabaseController(QObject): + def __init__(self, parent=None): super().__init__(parent) self.window = parent @@ -53,7 +61,7 @@ def ensure_sqlite_indices(self): @LegacyCode? """ if bw.databases and not sqlite3_lci_db._database.get_indexes('activitydataset'): - print("creating missing sqlite indices") + log.info("creating missing sqlite indices") bw.Database(list(bw.databases)[-1])._add_indices() @Slot(name="bw2Setup") diff --git a/activity_browser/controllers/plugin.py b/activity_browser/controllers/plugin.py index 5abe0b874..d7db65e22 100644 --- a/activity_browser/controllers/plugin.py +++ b/activity_browser/controllers/plugin.py @@ -11,6 +11,12 @@ from ..signals import signals from ..settings import project_settings, ab_settings +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class PluginController(QObject): @@ -47,16 +53,15 @@ def discover_plugins(self): def load_plugin(self, name): try: - print("Importing plugin {}".format(name)) + log.info("Importing plugin {}".format(name)) plugin_lib = importlib.import_module(name) importlib.reload(plugin_lib) return plugin_lib.Plugin() - except: - print("Error: Import of plugin {} failed".format(name)) - print(traceback.format_exc()) + except Exception as e: + log.error("Error: Import of plugin {} failed".format(name), error=e) def remove_plugin(self, name): - print("Removing plugin {}".format(name)) + log.info("Removing plugin {}".format(name)) # Apply plugin remove() function self.plugins[name].remove() # Close plugin tabs @@ -72,9 +77,9 @@ def add_plugin(self, name, select: bool = True): # Add plugins tabs for tab in plugin.tabs: self.window.add_tab_to_panel(tab, plugin.infos["name"], tab.panel) - print("Loaded tab {}".format(name)) + log.info("Loaded tab {}".format(name)) return - print("Removing plugin {}".format(name)) + log.info("Removing plugin {}".format(name)) # Apply plugin remove() function self.plugins[name].remove() # Close plugin tabs @@ -94,7 +99,7 @@ def reload_plugins(self): try: self.add_plugin(name) except: - print(f"Error: plugin {name} not installed") + log.error(f"Error: plugin {name} not installed") def close_plugins(self): """ close all plugins diff --git a/activity_browser/controllers/project.py b/activity_browser/controllers/project.py index 5a47730ae..40a3bd881 100644 --- a/activity_browser/controllers/project.py +++ b/activity_browser/controllers/project.py @@ -8,6 +8,12 @@ from activity_browser.signals import signals from activity_browser.ui.widgets import TupleNameDialog, ProjectDeletionDialog +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class ProjectController(QObject): """The controller that handles all of the AB features on the level of @@ -33,11 +39,11 @@ def switch_brightway2_dir_path(self, dirpath: str) -> None: def load_settings(self) -> None: if ab_settings.settings: - print("Loading user settings:") + log.info("Loading user settings:") self.switch_brightway2_dir_path(dirpath=ab_settings.current_bw_dir) self.change_project(ab_settings.startup_project) - print('Brightway2 data directory: {}'.format(bw.projects._base_data_dir)) - print('Brightway2 active project: {}'.format(bw.projects.current)) + log.info('Brightway2 data directory: {}'.format(bw.projects._base_data_dir)) + log.info('Brightway2 active project: {}'.format(bw.projects.current)) @staticmethod @Slot(str, name="changeProject") @@ -48,13 +54,13 @@ def change_project(name: str, reload: bool = False) -> None: # assert name, "No project name given." name = "default" if not name else name if name not in bw.projects: - print("Project does not exist: {}, creating!".format(name)) + log.info("Project does not exist: {}, creating!".format(name)) bw.projects.create_project(name) if name != bw.projects.current or reload: bw.projects.set_current(name) signals.project_selected.emit() - print("Loaded project:", name) + log.info("Loaded project:", name) @Slot(name="createProject") def new_project(self, name=None): @@ -141,7 +147,7 @@ def new_calculation_setup(self) -> None: return bw.calculation_setups[name] = {'inv': [], 'ia': []} signals.calculation_setup_selected.emit(name) - print("New calculation setup: {}".format(name)) + log.info("New calculation setup: {}".format(name)) @Slot(str, name="copyCalculationSetup") def copy_calculation_setup(self, current: str) -> None: @@ -155,13 +161,13 @@ def copy_calculation_setup(self, current: str) -> None: return bw.calculation_setups[new_name] = bw.calculation_setups[current].copy() signals.calculation_setup_selected.emit(new_name) - print("Copied calculation setup {} as {}".format(current, new_name)) + log.info("Copied calculation setup {} as {}".format(current, new_name)) @Slot(str, name="deleteCalculationSetup") def delete_calculation_setup(self, name: str) -> None: del bw.calculation_setups[name] signals.set_default_calculation_setup.emit() - print("Deleted calculation setup: {}".format(name)) + log.info("Deleted calculation setup: {}".format(name)) @Slot(str, name="renameCalculationSetup") def rename_calculation_setup(self, current: str) -> None: @@ -174,11 +180,9 @@ def rename_calculation_setup(self, current: str) -> None: if not self._can_use_cs_name(new_name): return bw.calculation_setups[new_name] = bw.calculation_setups[current].copy() - # print("Current setups:", list(bw.calculation_setups.keys())) del bw.calculation_setups[current] - # print("After deletion of {}:".format(current), list(bw.calculation_setups.keys())) signals.calculation_setup_selected.emit(new_name) - print("Renamed calculation setup from {} to {}".format(current, new_name)) + log.info("Renamed calculation setup from {} to {}".format(current, new_name)) def _can_use_cs_name(self, new_name: str) -> bool: if new_name in bw.calculation_setups.keys(): @@ -223,17 +227,17 @@ def copy_method(self, method: tuple, level: str = None) -> None: QtWidgets.QMessageBox.warning(self.window, "Copy failed", warn) return mthd.copy(new_method) - print("Copied method {} into {}".format(str(mthd.name), str(new_method))) + log.info("Copied method {} into {}".format(str(mthd.name), str(new_method))) signals.new_method.emit() @Slot(tuple, name="deleteMethod") - def delete_method(self, method: tuple, level:str = None) -> None: + def delete_method(self, method_: tuple, level:str = None) -> None: """Call delete on the (first) selected method and present confirmation dialog.""" if level is not None and level != 'leaf': - methods = [bw.Method(mthd) for mthd in bw.methods if set(method).issubset(mthd)] + methods = [bw.Method(mthd) for mthd in bw.methods if set(method_).issubset(mthd)] else: - methods = [bw.Method(method)] - method = bw.Method(method) + methods = [bw.Method(method_)] + method = bw.Method(method_) dialog = QtWidgets.QMessageBox() dialog.setWindowTitle("Are you sure you want to delete this method?") dialog.setText("You are about to PERMANENTLY delete the following Impact Category:\n(" @@ -245,8 +249,7 @@ def delete_method(self, method: tuple, level:str = None) -> None: if dialog.exec_() == QtWidgets.QMessageBox.Yes: for mthd in methods: mthd.deregister() - print("Deleted method {}".format(str(mthd.name))) - # TODO: ensure the method no longer shows up anywhere. + log.info("Deleted method {}".format(str(mthd.name))) signals.method_deleted.emit() @Slot(list, tuple, name="removeCFUncertainty") @@ -318,7 +321,6 @@ def delete_method_from_cf(self, to_delete: tuple, method: tuple): for d in to_delete: if i[0][0] == d[0][0] and i[0][1] == d[0][1]: delete_list.append(i) - print('yep same') for d in delete_list: cfs.remove(d) method.write(cfs) diff --git a/activity_browser/layouts/panels/panel.py b/activity_browser/layouts/panels/panel.py index afd5c5a38..40e5bbb20 100644 --- a/activity_browser/layouts/panels/panel.py +++ b/activity_browser/layouts/panels/panel.py @@ -3,6 +3,12 @@ from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class ABTab(QtWidgets.QTabWidget): def __init__(self, parent=None): @@ -45,7 +51,7 @@ def hide_tab(self, tab_name, current_index=0): if tab_name in self.tabs: tab = self.tabs[tab_name] if self.indexOf(tab) != -1: - print("-hiding tab:", tab_name) + log.info("-hiding tab:", tab_name) tab.setVisible(False) # Only explicitly alter the tab index if we're hiding the # current tab itself. @@ -57,7 +63,7 @@ def show_tab(self, tab_name): """Makes existing tab visible.""" if tab_name in self.tabs: tab = self.tabs[tab_name] - print("+showing tab:", tab_name) + log.info("+showing tab:", tab_name) tab.setVisible(True) self.addTab(tab, tab_name) self.select_tab(tab) @@ -68,7 +74,7 @@ def get_tab_name(self, obj): if len(tab_names) == 1: return tab_names[0] else: - print("Warning: found", len(tab_names), "occurences of this object.") + log.warning("found", len(tab_names), "occurences of this object.") def get_tab_name_from_index(self, index): """Return the name of a tab based on its index.""" @@ -80,11 +86,8 @@ def get_tab_name_from_index(self, index): def hide_when_empty(self): """Show tab if it has sub-tabs (not empty) or hide if it has no sub-tabs (empty).""" - # print("\nChecking for empty tabs:") for tab_name, tab in self.tabs.items(): - # print("Tab:", self.get_tab_name(tab), "...") if hasattr(tab, "tabs"): - # print("Subtabs:", tab.tabs.keys()) if not tab.tabs: self.hide_tab(tab_name) # else: # leads to strange behaviour of setCurrentIndex/select_tab @@ -94,7 +97,6 @@ def close_tab(self, index): """Close tab by index.""" widget = self.widget(index) tab_name = self.get_tab_name(widget) - # print("Closing tab:", tab_name) if widget in self.tabs.values(): del self.tabs[tab_name] widget.deleteLater() diff --git a/activity_browser/layouts/panels/right.py b/activity_browser/layouts/panels/right.py index 7b14bc951..0d1279d7b 100644 --- a/activity_browser/layouts/panels/right.py +++ b/activity_browser/layouts/panels/right.py @@ -16,6 +16,12 @@ from ...bwutils.commontasks import get_activity_name from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class RightPanel(ABTab): side = "right" @@ -49,7 +55,7 @@ def show_tab(self, tab_name): """ if tab_name in self.tabs: tab = self.tabs[tab_name] - print("+showing tab:", tab_name) + log.info("+showing tab:", tab_name) tab.setVisible(True) self.insertTab(self.tab_order[tab_name], tab, tab_name) self.select_tab(tab) @@ -77,7 +83,7 @@ def connect_signals(self): def add_tab(self, key, select=True): """Opens new tab or focuses on already open one.""" if key not in self.tabs: - print("adding graph tab") + log.info("adding graph tab") new_tab = GraphNavigatorWidget(self, key=key) self.tabs[key] = new_tab self.addTab(new_tab, get_activity_name(bw.get_activity(key), str_length=30)) diff --git a/activity_browser/layouts/tabs/LCA_results_tab.py b/activity_browser/layouts/tabs/LCA_results_tab.py index 51755bd77..cdf929fcf 100644 --- a/activity_browser/layouts/tabs/LCA_results_tab.py +++ b/activity_browser/layouts/tabs/LCA_results_tab.py @@ -10,6 +10,12 @@ from ...signals import signals from ...bwutils.errors import ABError +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class LCAResultsTab(ABTab): """Tab that contains subtabs for each calculation setup.""" @@ -61,7 +67,7 @@ def generate_setup(self, data: dict): signals.show_tab.emit("LCA results") except BW2CalcError as e: initial, *other = e.args - print(traceback.format_exc()) + log.error(traceback.format_exc()) msg = QMessageBox( QMessageBox.Warning, "Calculation problem", str(initial), QMessageBox.Ok, self diff --git a/activity_browser/layouts/tabs/LCA_results_tabs.py b/activity_browser/layouts/tabs/LCA_results_tabs.py index 399735caf..1bdac5070 100644 --- a/activity_browser/layouts/tabs/LCA_results_tabs.py +++ b/activity_browser/layouts/tabs/LCA_results_tabs.py @@ -36,6 +36,13 @@ from ...ui.web import SankeyNavigatorWidget from .base import BaseRightTab +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + + def get_header_layout(header_text: str) -> QVBoxLayout: vlayout = QVBoxLayout() vlayout.addWidget(header(header_text)) @@ -160,7 +167,7 @@ def update_scenario_data(self, index: int) -> None: def generate_content_on_click(self, index): if index == self.indexOf(self.tabs.sankey): if not self.tabs.sankey.has_sankey: - print('Generating Sankey Tab') + log.info('Generating Sankey Tab') self.tabs.sankey.new_sankey() @QtCore.Slot(name="lciaScenarioExport") @@ -1218,11 +1225,11 @@ def calculate_mc_lca(self): iterations = int(self.iterations.text()) seed = None if self.seed.text(): - print('SEED: ', self.seed.text()) + log.info('SEED: ', self.seed.text()) try: seed = int(self.seed.text()) - except ValueError: - traceback.print_exc() + except ValueError as e: + log.error('Seed value must be an integer number or left empty.', error=e) QMessageBox.warning(self, 'Warning', 'Seed value must be an integer number or left empty.') self.seed.setText('') return @@ -1240,7 +1247,7 @@ def calculate_mc_lca(self): self.update_mc() except InvalidParamsError as e: # This can occur if uncertainty data is missing or otherwise broken # print(e) - traceback.print_exc() + log.error(error=e) QMessageBox.warning(self, 'Could not perform Monte Carlo simulation', str(e)) QApplication.restoreOverrideCursor() @@ -1490,7 +1497,7 @@ def calculate_gsa(self): cutoff_technosphere=cutoff_technosphere, cutoff_biosphere=cutoff_biosphere) # self.update_mc() except Exception as e: # Catch any error... - traceback.print_exc() + log.error(error=e) message = str(e) message_addition = '' if message == 'singular matrix': @@ -1516,7 +1523,7 @@ def update_gsa(self, cs_name=None): self.table.table_name = 'gsa_output_' + self.GSA.get_save_name() if self.checkbox_export_data_automatically.isChecked(): - print("EXPORTING DATA") + log.info("EXPORTING DATA") self.GSA.export_GSA_input() self.GSA.export_GSA_output() @@ -1556,15 +1563,18 @@ class MonteCarloWorkerThread(QtCore.QThread): Unfortunately, pyparadiso does not allow parallel calculations on Windows (crashes). So this is for future reference in case this issue is solved... """ + def __init__(self): + pass + def set_mc(self, mc, iterations=20): self.mc = mc self.iterations = iterations def run(self): - print('Starting new Worker Thread. Iterations:', self.iterations) + log.info('Starting new Worker Thread. Iterations:', self.iterations) self.mc.calculate(iterations=self.iterations) # res = bw.GraphTraversal().calculate(self.demand, self.method, self.cutoff, self.max_calc) - print('in thread {}'.format(QtCore.QThread.currentThread())) + log.info('in thread {}'.format(QtCore.QThread.currentThread())) signals.monte_carlo_ready.emit(self.mc.cs_name) diff --git a/activity_browser/layouts/tabs/LCA_setup.py b/activity_browser/layouts/tabs/LCA_setup.py index 3acd4a071..03259f7d1 100644 --- a/activity_browser/layouts/tabs/LCA_setup.py +++ b/activity_browser/layouts/tabs/LCA_setup.py @@ -20,6 +20,12 @@ from ...ui.widgets import ExcelReadDialog from .base import BaseRightTab +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + """ Lifecycle of a calculation setup ================================ @@ -456,9 +462,9 @@ def load_action(self) -> None: idx = dialog.import_sheet.currentIndex() file_type_suffix = dialog.path.suffix separator = dialog.field_separator.currentData() - print("separator == '{}'".format(separator)) + log.info("separator == '{}'".format(separator)) QtWidgets.QApplication.setOverrideCursor(Qt.WaitCursor) - print('Loading Scenario file. This may take a while for large files') + log.info('Loading Scenario file. This may take a while for large files') try: # Try and read as a superstructure file if file_type_suffix == ".feather": @@ -477,7 +483,7 @@ def load_action(self) -> None: self.sync_superstructure(df) except (IndexError, ValueError) as e: # Try and read as parameter scenario file. - print("Superstructure: {}\nAttempting to read as parameter scenario file.".format(e)) + log.error("Superstructure: {}\nAttempting to read as parameter scenario file.".format(e)) df = pd.read_excel(path, sheet_name=idx, engine="openpyxl") include_default = True if "default" not in df.columns: @@ -508,5 +514,5 @@ def sync_superstructure(self, df: pd.DataFrame) -> None: @property def dataframe(self) -> pd.DataFrame: if self.scenario_df.empty: - print("No data in scenario table {}, skipping".format(self.index + 1)) + log.warning("No data in scenario table {}, skipping".format(self.index + 1)) return self.scenario_df diff --git a/activity_browser/layouts/tabs/debug.py b/activity_browser/layouts/tabs/debug.py index e2713b895..443e89bcf 100644 --- a/activity_browser/layouts/tabs/debug.py +++ b/activity_browser/layouts/tabs/debug.py @@ -1,9 +1,10 @@ -from PySide2 import QtWidgets +from PySide2 import QtWidgets, QtCore import sys from ..panels import ABTab from ...ui.style import header from ...ui.utils import StdRedirector +from ...signals import signals class DebugTab(ABTab): @@ -11,9 +12,9 @@ class DebugTab(ABTab): def __init__(self, parent = None): super(DebugTab, self).__init__(parent) - self.log = QtWidgets.QTextEdit(self) - sys.stdout = StdRedirector(self.log, sys.stdout, None) - sys.stderr = StdRedirector(self.log, sys.stderr, "blue") + self.log = QtWidgets.QPlainTextEdit(self) + sys.stdout = StdRedirector(self.log, sys.stdout) + sys.stderr = StdRedirector(self.log, sys.stderr) self.debug_display = QtWidgets.QVBoxLayout() self.title = header('Program debugger output:') @@ -23,3 +24,10 @@ def __init__(self, parent = None): self.setLayout(self.debug_display) self.setVisible(False) + + signals.log.connect(self.write_log_message) + + @QtCore.Slot(name="writeLogMessage") + def write_log_message(self, msg: str): + self.log.appendPlainText(msg) + self.log.centerCursor() \ No newline at end of file diff --git a/activity_browser/layouts/tabs/impact_categories.py b/activity_browser/layouts/tabs/impact_categories.py index 7d497192f..8f751e3f9 100644 --- a/activity_browser/layouts/tabs/impact_categories.py +++ b/activity_browser/layouts/tabs/impact_categories.py @@ -57,7 +57,6 @@ def cf_read_only_changed(self, editable: bool) -> None: self.cf_table.setEditTriggers(QtWidgets.QTableView.DoubleClicked) else: self.cf_table.setEditTriggers(QtWidgets.QTableView.NoEditTriggers) - print(self.read_only) class MethodsTab(QtWidgets.QWidget): def __init__(self, parent): diff --git a/activity_browser/logger.py b/activity_browser/logger.py new file mode 100644 index 000000000..b413bfe38 --- /dev/null +++ b/activity_browser/logger.py @@ -0,0 +1,173 @@ +from PySide2.QtCore import Slot +import logging +import os, time, appdirs +import random, string + +from .signals import signals + + +class ABHandler(object): + """ + Creates two logging streams, one to the console (with >=INFORMATION logs) + the second to a file specified with the name argument (with >=WARNING logs) + and attaches these to a logger created in the calling modules. + + Provides the formats and initialization procedures for the logging streams. + """ + log = None + file_path = None + stream_handler = None + file_handler = None + qt_handler = None + + def __init__(self, name: str = None): + self.module_name = name + + @staticmethod + def initialize_with_logger(logger: logging.Logger): + """ + Will initialize the handlers for the logging streams and check that the file handler + is properly setup before linking to the passed Logger object. + + Parameters + ---------- + logger: an object of type logging.Logger obtained in the calling module with getLogger() + """ + name = logger.name + ABHandler.timestamp() + '.log' + dir_path = appdirs.user_log_dir('ActivityBrowser', 'ActivityBrowser') + os.makedirs(dir_path, exist_ok=True) + ABHandler.clean_directory(dir_path) + ABHandler.file_path = dir_path + "/" + name + ABHandler.stream_handler = logging.StreamHandler() + ABHandler.file_handler = logging.FileHandler(ABHandler.file_path) + + log_format = logging.Formatter("%(asctime)s - %(levelname)s - %(ABmodule)s - %(message)s - ") + + console_format = logging.Formatter("%(message)s") + ABHandler.stream_handler.setFormatter(console_format) + ABHandler.file_handler.setFormatter(log_format) + + ABHandler.stream_handler.setLevel(logging.INFO) + ABHandler.file_handler.setLevel(logging.DEBUG) + + ABHandler.qt_handler = ABLogHandler() + ABHandler.qt_handler.setFormatter(console_format) + + return ABHandler.setup_with_logger(logger) + + @classmethod + def setup_with_logger(cls, logger: logging.Logger = None, module: str = None): + """ + Links the logger object to the different stream handlers. This avoids the process of + creating new handlers and should be the general method to call for linking the + logging.Logger objects. + + Parameters + ---------- + logger: an object of type logging.Logger requiring setup with logging.Handlers + """ + + ABHandler.log = logger + assert ABHandler.log is not None + + ABHandler.log.addHandler(ABHandler.stream_handler) + ABHandler.log.addHandler(ABHandler.file_handler) + ABHandler.log.addHandler(ABHandler.qt_handler) + ABHandler.log.setLevel(logging.INFO) + + if module is not None: + return ABHandler(module) + return ABHandler("root") + + @staticmethod + def unique_string(n: int) -> str: + """Returns a random string of length n, to avoid issues with non-unique log files""" + return ''.join(random.choice(string.ascii_letters) for i in range(n)) + + @staticmethod + def timestamp() -> str: + """Returns a timestamped string, the format provided is: + day of the month _ month _ year - hour _ minute _ second""" + stmp = time.localtime() + return f"-{stmp.tm_mday}_{stmp.tm_mon}_{stmp.tm_year}-{stmp.tm_hour}_{stmp.tm_min}_{stmp.tm_sec}" + + @staticmethod + def clean_directory(dirpath: str) -> None: + """Cleans the Activity-Browser/log directory of all files older than 365 days""" + time_limit = time.time() - 24*3600*365 + for file in os.listdir(dirpath): + filepath = dirpath + '/' + file + if os.stat(filepath).st_mtime < time_limit: + os.remove(filepath) + + def log_file_path(self): + return ABHandler.file_path + + def message(self, *args) -> str: + _str = '' + for arg in args: + if not isinstance(arg, str): + _str += str(arg) + else: + _str += arg + return _str + + def debug(self, msg: str, *args) -> None: + ABHandler.log.debug(self.message(msg, *args), extra={'ABmodule': self.module_name}) + + def info(self, msg: str, *args) -> None: + ABHandler.log.info(self.message(msg, *args), extra={'ABmodule': self.module_name}) + + def warning(self, msg: str, *args) -> None: + ABHandler.log.warning(self.message(msg, *args), extra={'ABmodule': self.module_name}) + + def error(self, msg: str = None, *args, **kwargs) -> None: + """ Provides a wrapper for the Logger.error method. This is to keep the logging messages + consistent with previous practices. Exception handling is provided through the use of + kwargs + Parameters: + msg, *args: strings that form the logging message, multiple strings allowed + **kwargs: provided for the handling of stack traces, the two arguments taken here are: + error='' + exc_info=bool + """ + if msg is not None: + ABHandler.log.error(self.message(msg, *args), extra={'ABmodule': self.module_name}) + + exc_info = True # TODO Move this error handling with the use of kwargs into a single error message + if kwargs and 'error' in kwargs: + if 'exc_info' in kwargs: + exc_info = kwargs['exc_info'] + ABHandler.log.error(kwargs['error'], exc_info=exc_info) + + def addHandler(self, handler) -> None: + ABHandler.log.addHandler(handler) + + def setLevel(self, level, root: bool = False) -> None: + if root: + ABHandler.log.root.setLevel(level) + else: + ABHandler.log.setLevel(level) + + +class ABLogHandler(logging.Handler): + """Customizing a handler for running within a separate thread, emitting logs to the main + thread.""" + def __init__(self): + super().__init__() + self.setLevel(logging.INFO) + + def emit(self, record): + msg = self.format(record) + signals.log.emit(msg) + + +logger = logging.getLogger('ab_logs') +log = ABHandler.initialize_with_logger(logger) + +#handler = ABLogHandler() +#handler.setFormatter(logging.Formatter("%(module)s - %(levelname)s - %(asctime)s - %(message)s")) +#log = ABHandler('ab_logs') +#log.addHandler(handler) +#log.propagate = True +#logging.setLoggerClass(ABHandler) diff --git a/activity_browser/settings.py b/activity_browser/settings.py index 85b34d878..29248a688 100644 --- a/activity_browser/settings.py +++ b/activity_browser/settings.py @@ -10,11 +10,17 @@ import brightway2 as bw from .signals import signals +import logging +from .logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) class BaseSettings(object): """ Base Class for handling JSON settings files. """ + def __init__(self, directory: str, filename: str = None): self.data_dir = directory self.filename = filename or "default_settings.json" @@ -236,7 +242,7 @@ def reset_for_project_selection(self) -> None: """ On switching project, attempt to read the settings for the new project. """ - print("Reset project settings directory to:", bw.projects.dir) + log.info("Reset project settings directory to:", bw.projects.dir) self.settings_file = os.path.join(bw.projects.dir, self.filename) self.initialize_settings() # create a plugins_list entry for old projects diff --git a/activity_browser/signals.py b/activity_browser/signals.py index 9c6ed76ca..f57574406 100644 --- a/activity_browser/signals.py +++ b/activity_browser/signals.py @@ -7,6 +7,7 @@ class Signals(QObject): While arguments can be passed to signals, it is good practice not to do this if possible. """ # General Settings + log = Signal(str) # bw2 directory switch_bw2_dir_path = Signal(str) diff --git a/activity_browser/ui/figures.py b/activity_browser/ui/figures.py index a00f84ad1..d1eeb0f23 100644 --- a/activity_browser/ui/figures.py +++ b/activity_browser/ui/figures.py @@ -13,6 +13,12 @@ from activity_browser.utils import savefilepath from ..bwutils.commontasks import wrap_text +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + # todo: sizing of the figures needs to be improved and systematized... # todo: Bokeh is a potential alternative as it allows interactive visualizations, @@ -278,7 +284,7 @@ def plot(self, data: np.ndarray, mean: float, label: str = "Value"): try: sns.histplot(data.T, kde=True, stat="density", ax=self.ax, edgecolor="none") except RuntimeError as e: - print("Runtime error: {}\nPlotting without KDE.".format(e)) + log.error("{}: Plotting without KDE.".format(e)) sns.histplot(data.T, kde=False, stat="density", ax=self.ax, edgecolor="none") self.ax.set_xlabel(label) self.ax.set_ylabel("Probability density") diff --git a/activity_browser/ui/statusbar.py b/activity_browser/ui/statusbar.py index 210ea64a0..e40743c78 100644 --- a/activity_browser/ui/statusbar.py +++ b/activity_browser/ui/statusbar.py @@ -6,6 +6,11 @@ from ..signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) class Statusbar(QStatusBar): def __init__(self, window): @@ -27,7 +32,7 @@ def connect_signals(self): @Slot(str, name="statusLeft") def left(self, message: str) -> None: - print(message) # for console output + log.info(message) # for console output if isinstance(message, str): self.status_message_left.setText(message) diff --git a/activity_browser/ui/tables/LCA_setup.py b/activity_browser/ui/tables/LCA_setup.py index cc0f4321d..d2a4dc488 100644 --- a/activity_browser/ui/tables/LCA_setup.py +++ b/activity_browser/ui/tables/LCA_setup.py @@ -10,6 +10,11 @@ from .models import CSMethodsModel, CSActivityModel, ScenarioImportModel from .views import ABDataFrameView +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) class CSList(QtWidgets.QComboBox): def __init__(self, parent=None): @@ -128,7 +133,7 @@ def dropEvent(self, event): event.accept() source = event.source() if getattr(event.source(), "technosphere", False): - print('Dropevent from:', source) + log.info('Dropevent from:', source) self.model.include_activities( {source.get_key(p): 1.0} for p in source.selectedIndexes() ) @@ -152,6 +157,7 @@ def __init__(self, parent=None): "Click and drag to re-order individual rows of the table\n" "Hold CTRL and click to select multiple rows to open or delete them.") + @Slot(name="resizeView") def custom_view_sizing(self): self.setColumnHidden(3, True) diff --git a/activity_browser/ui/tables/models/activity.py b/activity_browser/ui/tables/models/activity.py index 8232acc35..97a640fa9 100644 --- a/activity_browser/ui/tables/models/activity.py +++ b/activity_browser/ui/tables/models/activity.py @@ -16,6 +16,12 @@ from activity_browser.signals import signals from .base import EditablePandasModel +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class BaseExchangeModel(EditablePandasModel): COLUMNS = [] @@ -59,7 +65,7 @@ def create_row(self, exchange) -> dict: return row except DoesNotExist as e: # The input activity does not exist. remove the exchange. - print("Broken exchange: {}, removing.".format(e)) + log.info("Broken exchange: {}, removing.".format(e)) signals.exchanges_deleted.emit([exchange]) def get_exchange(self, proxy: QModelIndex) -> ExchangeProxyBase: @@ -118,7 +124,6 @@ def copy_exchanges_for_SDF(self, proxies: list) -> None: continue # exact duplicate entry into clipboard prev = e exchanges.append(e) - print(exchanges) data = bc.get_exchanges_in_scenario_difference_file_notation(exchanges) df = pd.DataFrame(data) df.to_clipboard(excel=True, index=False) @@ -200,7 +205,7 @@ def get_interpreter(self) -> Interpreter: if act: interpreter.symtable.update(ActivityParameter.static(act.group, full=True)) else: - print("No parameter found for {}, creating one on formula save".format(self.key)) + log.info("No parameter found for {}, creating one on formula save".format(self.key)) interpreter.symtable.update(ProjectParameter.static()) interpreter.symtable.update(DatabaseParameter.static(self.key[0])) return interpreter @@ -255,7 +260,7 @@ def create_row(self, exchange: ExchangeProxyBase) -> dict: }) return row except DoesNotExist as e: - print("Exchange was deleted, continue.") + log.info("Exchange was deleted, continue.") return {} @@ -297,7 +302,7 @@ def create_row(self, exchange) -> dict: }) return row except DoesNotExist as e: - print("Exchange was deleted, continue.") + log.info("Exchange was deleted, continue.") return {} diff --git a/activity_browser/ui/tables/models/base.py b/activity_browser/ui/tables/models/base.py index 9659042da..e2b321d90 100644 --- a/activity_browser/ui/tables/models/base.py +++ b/activity_browser/ui/tables/models/base.py @@ -11,6 +11,12 @@ from activity_browser.bwutils import commontasks as bc from activity_browser.ui.style import style_item +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class PandasModel(QAbstractTableModel): """ Abstract pandas table model adapted from @@ -30,10 +36,10 @@ def __init__(self, df: pd.DataFrame = None, parent=None): self.different_column_types = {} def rowCount(self, parent=None, *args, **kwargs): - return self._dataframe.shape[0] + return 0 if self._dataframe is None else self._dataframe.shape[0] def columnCount(self, parent=None, *args, **kwargs): - return self._dataframe.shape[1] + return 0 if self._dataframe is None else self._dataframe.shape[1] def data(self, index, role=Qt.DisplayRole): if not index.isValid(): @@ -130,7 +136,7 @@ def test_query_on_column(self, test_type: str, col_data: pd.Series, query) -> pd return (float(query[0]) <= col_data.astype(float)) \ & (col_data.astype(float) <= float(query[1])) else: - print("WARNING: unknown filter type >{}<, assuming 'EQUALS'".format(test_type)) + log.warning("unknown filter type >{}<, assuming 'EQUALS'".format(test_type)) return col_data == query def get_filter_mask(self, filters: dict) -> pd.Series: @@ -170,7 +176,7 @@ def get_filter_mask(self, filters: dict) -> pd.Series: new_mask = self.test_query_on_column(filt_type, col_data_, query) if not any(new_mask): # no matches for this mask, let user know: - print("There were no matches for filter: {}: '{}'".format(col_filt[0], col_filt[1])) + log.info("There were no matches for filter: {}: '{}'".format(col_filt[0], col_filt[1])) # create or combine new mask within column if isinstance(col_mask, pd.Series) and col_mode == 'AND': diff --git a/activity_browser/ui/tables/models/impact_categories.py b/activity_browser/ui/tables/models/impact_categories.py index c004d9418..594210db6 100644 --- a/activity_browser/ui/tables/models/impact_categories.py +++ b/activity_browser/ui/tables/models/impact_categories.py @@ -14,6 +14,12 @@ from ...wizards import UncertaintyWizard from .base import EditablePandasModel, DragPandasModel, TreeItem, BaseTreeModel +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class MethodsListModel(DragPandasModel): HEADERS = ["Name", "Unit", "# CFs", "method"] @@ -370,7 +376,6 @@ def remove_uncertainty(self, proxy_indexes: Iterator[QModelIndex]) -> None: @Slot(list, name="deleteCF") def delete_cf(self, proxy_indexes: Iterator[QModelIndex]) -> None: to_delete = [self.get_cf(p) for p in proxy_indexes] - print(to_delete) confirm = QMessageBox() confirm.setIcon(QMessageBox.Warning) confirm.setWindowTitle("Confirm deletion") @@ -378,7 +383,7 @@ def delete_cf(self, proxy_indexes: Iterator[QModelIndex]) -> None: confirm.setStandardButtons(QMessageBox.Ok | QMessageBox.Cancel) confirmed = confirm.exec() if confirmed == QMessageBox.Ok: - print("Deleting CF(s):", to_delete) + log.info("Deleting CF(s):", to_delete) signals.delete_cf_method.emit(to_delete, self.method.name) @Slot(tuple, object, name="modifyCf") diff --git a/activity_browser/ui/tables/models/inventory.py b/activity_browser/ui/tables/models/inventory.py index 6e672aeb9..1b72c2996 100644 --- a/activity_browser/ui/tables/models/inventory.py +++ b/activity_browser/ui/tables/models/inventory.py @@ -15,6 +15,12 @@ from activity_browser.signals import signals from .base import PandasModel, DragPandasModel +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class DatabasesModel(PandasModel): HEADERS = ["Name", "Records", "Read-only", "Depends", "Modified"] @@ -99,7 +105,7 @@ def df_from_metadata(self, db_name: str) -> pd.DataFrame: def sync(self, db_name: str, df: pd.DataFrame = None) -> None: if df is not None: # skip the rest of the sync here if a dataframe is directly supplied - print("Pandas Dataframe passed to sync.", df.shape) + log.info("Pandas Dataframe passed to sync.", df.shape) self._dataframe = df self.updated.emit() return diff --git a/activity_browser/ui/tables/models/lca_setup.py b/activity_browser/ui/tables/models/lca_setup.py index aab6e885b..dac356af2 100644 --- a/activity_browser/ui/tables/models/lca_setup.py +++ b/activity_browser/ui/tables/models/lca_setup.py @@ -11,6 +11,12 @@ from activity_browser.signals import signals from .base import EditablePandasModel, PandasModel +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class CSGenericModel(EditablePandasModel): """ Intermediate class to enable internal move functionality for the @@ -130,7 +136,7 @@ def build_row(self, key: tuple, amount: float = 1.0) -> dict: row.update({"Amount": amount, "key": key}) return row except (TypeError, ActivityDataset.DoesNotExist): - print("Could not load key in Calculation Setup: ", key) + log.error("Could not load key '{}' in Calculation Setup '{}'".format(str(key), self.current_cs)) return {} @Slot(name="deleteRows") @@ -159,11 +165,36 @@ class CSMethodsModel(CSGenericModel): def __init__(self, parent=None): super().__init__(parent=parent) self.current_cs = None - signals.calculation_setup_selected.connect(self.sync) + signals.calculation_setup_selected.connect(self.update_cs) + signals.method_deleted.connect( + lambda: self.update_cs(self.current_cs)) @property def methods(self) -> list: - return self._dataframe.loc[:, "method"].to_list() + return [] if self._dataframe is None else self._dataframe.loc[:, "method"].to_list() + + @Slot(name="UpdateBWCalculationSetup") + def update_cs(self, name: str = None) -> None: + """Updates and syncs the bw.calculation_setups for the Impact categories. Removes any + Impact category from a calculation setup if it is not present in the current environment""" + def filter_methods(cs): + """Filters any methods out from the calculation setup if they aren't in bw.methods""" + i = 0 + while i < len(cs): + if cs[i] not in bw.methods: + cs.pop(i) + else: + i += 1 + ######## END OF FUNCTION + + if self.current_cs is not None or name is not None: + self.current_cs = name + filter_methods(bw.calculation_setups[self.current_cs].get('ia', [])) + self.sync(self.current_cs) + else: + for name, cs in bw.calculation_setups.items(): + filter_methods(cs['ia']) + self.sync() @Slot(str, name="syncModel") def sync(self, name: str = None) -> None: diff --git a/activity_browser/ui/tables/models/parameters.py b/activity_browser/ui/tables/models/parameters.py index 75301f0a2..715516db3 100644 --- a/activity_browser/ui/tables/models/parameters.py +++ b/activity_browser/ui/tables/models/parameters.py @@ -15,6 +15,12 @@ from activity_browser.ui.wizards import UncertaintyWizard from .base import BaseTreeModel, EditablePandasModel, TreeItem +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class BaseParameterModel(EditablePandasModel): COLUMNS = [] @@ -232,7 +238,7 @@ def parse_parameter(cls, parameter) -> dict: act = bw.get_activity(row["key"]) except: # Can occur if an activity parameter exists for a removed activity. - print("Activity {} no longer exists, removing parameter.".format(row["key"])) + log.info("Activity {} no longer exists, removing parameter.".format(row["key"])) signals.clear_activity_parameter.emit( parameter.database, parameter.code, parameter.group ) @@ -354,7 +360,7 @@ def build_exchanges(cls, act_param, parent: TreeItem) -> None: parent.appendChild(item) except DoesNotExist as e: # The exchange is coming from a deleted database, remove it - print("Broken exchange: {}, removing.".format(e)) + log.warning("Broken exchange: {}, removing.".format(e)) signals.exchanges_deleted.emit([exc]) diff --git a/activity_browser/ui/tables/views.py b/activity_browser/ui/tables/views.py index bd8ac6355..fdef08653 100644 --- a/activity_browser/ui/tables/views.py +++ b/activity_browser/ui/tables/views.py @@ -14,6 +14,12 @@ from .delegates import ViewOnlyDelegate from .models import PandasModel +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class ABDataFrameView(QTableView): """ Base class for showing pandas dataframe objects as tables. @@ -523,7 +529,7 @@ def set_filters(self, mask) -> None: self.activate_filter = True self.invalidateFilter() self.activate_filter = False - print('{} filter matches found'.format(self.matches)) + log.info('{} filter matches found'.format(self.matches)) def clear_filters(self) -> None: self.mask = None diff --git a/activity_browser/ui/web/base.py b/activity_browser/ui/web/base.py index 35f3f5479..47aaa78a9 100644 --- a/activity_browser/ui/web/base.py +++ b/activity_browser/ui/web/base.py @@ -15,6 +15,12 @@ from ...ui.icons import qicons from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class BaseNavigatorWidget(QtWidgets.QWidget): HELP_TEXT = """ @@ -140,7 +146,7 @@ def node_clicked(self, click_text: str): """ click_dict = json.loads(click_text) click_dict["key"] = (click_dict["database"], click_dict["id"]) # since JSON does not know tuples - print("Click information: ", click_dict) + log.info("Click information: ", click_dict) # TODO click_dict needs correcting self.update_graph.emit(click_dict) @Slot(str, name="download_triggered") diff --git a/activity_browser/ui/web/navigator.py b/activity_browser/ui/web/navigator.py index d7bb1fb32..761b45848 100644 --- a/activity_browser/ui/web/navigator.py +++ b/activity_browser/ui/web/navigator.py @@ -14,6 +14,12 @@ from ...signals import signals from ...bwutils.commontasks import identify_activity_type +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + # TODO: # save graph as image # zoom reverse direction between canvas and minimap @@ -154,12 +160,12 @@ def is_expansion_mode(self) -> bool: def toggle_navigation_mode(self): mode = next(self.navigation_label) self.button_navigation_mode.setText(mode) - print("Switched to:", mode) + log.info("Switched to:", mode) self.checkbox_remove_orphaned_nodes.setVisible(self.is_expansion_mode) self.checkbox_direct_only.setVisible(self.is_expansion_mode) def new_graph(self, key: tuple) -> None: - print("New Graph for key: ", key) + log.info("New Graph for key: ", key) self.graph.new_graph(key) self.send_json() @@ -188,15 +194,15 @@ def update_graph(self, click_dict: dict) -> None: self.new_graph(key) else: if keyboard["alt"]: # delete node - print("Deleting node: ", key) + log.info("Deleting node: ", key) self.graph.reduce_graph(key) else: # expansion mode - print("Expanding graph: ", key) + log.info("Expanding graph: ", key) if keyboard["shift"]: # downstream expansion - print("Adding downstream nodes.") + log.info("Adding downstream nodes.") self.graph.expand_graph(key, down=True) else: # upstream expansion - print("Adding upstream nodes.") + log.info("Adding upstream nodes.") self.graph.expand_graph(key, up=True) self.send_json() @@ -332,7 +338,7 @@ def reduce_graph(self, key: tuple) -> None: Can lead to orphaned nodes, which can be removed or kept. """ if key == self.central_activity.key: - print("Cannot remove central activity.") + log.warning("Cannot remove central activity.") return act = bw.get_activity(key) self.nodes.remove(act) @@ -376,9 +382,9 @@ def format_as_weighted_edges(exchanges, activity_objects=False): count = 1 for count, key in enumerate(orphaned_node_ids, 1): act = bw.get_activity(key) - print(act["name"], act["location"]) + log.info(act["name"], act["location"]) self.nodes.remove(act) - print("\nRemoved ORPHANED nodes:", count) + log.info("\nRemoved ORPHANED nodes:", count) # update edges again to remove those that link to nodes that have been deleted self.remove_outside_exchanges() @@ -394,7 +400,7 @@ def get_json_data(self) -> Optional[str]: A JSON representation of this. """ if not self.nodes: - print("Graph has no nodes (activities).") + log.info("Graph has no nodes (activities).") return data = { diff --git a/activity_browser/ui/web/sankey_navigator.py b/activity_browser/ui/web/sankey_navigator.py index e85ba57eb..ca5c6f5d3 100644 --- a/activity_browser/ui/web/sankey_navigator.py +++ b/activity_browser/ui/web/sankey_navigator.py @@ -14,6 +14,12 @@ from ...bwutils.superstructure.graph_traversal_with_scenario import GraphTraversalWithScenario from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + # TODO: # switch between percent and absolute values @@ -208,7 +214,7 @@ def update_calculation_setup(self, cs_name=None) -> None: self.method_cb.blockSignals(False) def new_sankey(self) -> None: - print("New Sankey for CS: ", self.cs) + log.info("New Sankey for CS: ", self.cs) demand_index = self.func_unit_cb.currentIndex() method_index = self.method_cb.currentIndex() @@ -228,7 +234,7 @@ def update_sankey(self, demand, method, scenario_index: int = None, method_index scenario_lca: bool = False, cut_off=0.05, max_calc=100) -> None: """Calculate LCA, do graph traversal, get JSON graph data for this, and send to javascript.""" - print("Demand / Method: {} {}".format(demand, method)) + log.info("Demand / Method: {} {}".format(demand, method)) start = time.time() try: @@ -240,7 +246,7 @@ def update_sankey(self, demand, method, scenario_index: int = None, method_index except ValueError as e: QtWidgets.QMessageBox.information(None, "Not possible.", str(e)) - print("Completed graph traversal ({:.2g} seconds, {} iterations)".format(time.time() - start, data["counter"])) + log.info("Completed graph traversal ({:.2g} seconds, {} iterations)".format(time.time() - start, data["counter"])) self.graph.new_graph(data) self.has_sankey = bool(self.graph.json_data) diff --git a/activity_browser/ui/web/webutils.py b/activity_browser/ui/web/webutils.py index 53a38c197..1b4bd7a56 100644 --- a/activity_browser/ui/web/webutils.py +++ b/activity_browser/ui/web/webutils.py @@ -4,7 +4,6 @@ # type "localhost:3999" in Chrome for DevTools of AB web content from activity_browser.utils import get_base_path - os.environ['QTWEBENGINE_REMOTE_DEBUGGING'] = '3999' diff --git a/activity_browser/ui/widgets/biosphere_update.py b/activity_browser/ui/widgets/biosphere_update.py index 118e07caa..a7541c417 100644 --- a/activity_browser/ui/widgets/biosphere_update.py +++ b/activity_browser/ui/widgets/biosphere_update.py @@ -6,6 +6,12 @@ import bw2io.data as data from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) + class BiosphereUpdater(QtWidgets.QProgressDialog): def __init__(self, parent=None): @@ -48,5 +54,5 @@ def run(self): update_bio = getattr(data, patch) update_bio() except ValidityError as e: - print("Could not patch biosphere: {}".format(str(e))) + log.error("Could not patch biosphere: {}".format(str(e))) self.exit(1) diff --git a/activity_browser/ui/wizards/db_import_wizard.py b/activity_browser/ui/wizards/db_import_wizard.py index 30f579db4..a94eddab2 100644 --- a/activity_browser/ui/wizards/db_import_wizard.py +++ b/activity_browser/ui/wizards/db_import_wizard.py @@ -1,7 +1,6 @@ # -*- coding: utf-8 -*- import io from pathlib import Path -from pprint import pprint import subprocess import tempfile import zipfile @@ -23,6 +22,12 @@ from ..style import style_group_box from ..widgets import DatabaseLinkingDialog +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger) + # TODO: Rework the entire import wizard, the amount of different classes # and interwoven connections makes the entire thing nearly incomprehensible. @@ -108,7 +113,7 @@ def closeEvent(self, event): event.accept() def cancel_thread(self): - print('\nDatabase import interrupted!') + log.info('\nDatabase import interrupted!') import_signals.cancel_sentinel = True self.cleanup() @@ -824,7 +829,7 @@ def run_local_import(self): # With the changes to the ABExcelImporter and ABPackage classes # this should not really trigger for data exported from AB. if db.name != self.db_name: - print("WARNING: renaming database '{}' to '{}', parameters lost.".format( + log.warning("renaming database '{}' to '{}', parameters lost.".format( db.name, self.db_name)) db.rename(self.db_name) import_signals.db_progress.emit(1, 1) @@ -850,7 +855,7 @@ def run_local_import(self): ) except StrategyError as e: # Excel import failed because extra databases were found, relink -# print("Could not link exchanges, here are 10 examples.:") # THREAD UNSAFE FUNCTIONS + log.error("Could not link exchanges, here are 10 examples.:") # THREAD UNSAFE FUNCTIONS # pprint(e.args[0]) self.delete_canceled_db() import_signals.links_required.emit(e.args[0], e.args[1]) @@ -871,7 +876,7 @@ def run_local_import(self): def delete_canceled_db(self): if self.db_name in bw.databases: del bw.databases[self.db_name] - print(f'Database {self.db_name} deleted!') + log.info(f'Database {self.db_name} deleted!') class EcoinventLoginPage(QtWidgets.QWizardPage): @@ -1151,7 +1156,7 @@ def extract(cls, dirpath: str, db_name: str, *args, **kwargs): dir_path = str(dir_path) for i, filename in enumerate(file_list, start=1): if import_signals.cancel_sentinel: - print(f'Extraction canceled at position {i}!') + log.info(f'Extraction canceled at position {i}!') raise ImportCanceledError data.append(cls.extract_activity(dir_path, filename, db_name)) @@ -1172,7 +1177,7 @@ def _efficient_write_many_data(self, *args, **kwargs): def _efficient_write_dataset(self, *args, **kwargs): index = args[0] if import_signals.cancel_sentinel: - print(f'\nWriting canceled at position {index}!') + log.info(f'\nWriting canceled at position {index}!') raise ImportCanceledError import_signals.db_progress.emit(index+1, self.total) return super()._efficient_write_dataset(*args, **kwargs) diff --git a/activity_browser/ui/wizards/settings_wizard.py b/activity_browser/ui/wizards/settings_wizard.py index db3f56e7a..04cd7aa4f 100644 --- a/activity_browser/ui/wizards/settings_wizard.py +++ b/activity_browser/ui/wizards/settings_wizard.py @@ -8,6 +8,12 @@ from ...settings import ab_settings from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger) + class SettingsWizard(QtWidgets.QWizard): def __init__(self, parent=None): @@ -30,7 +36,7 @@ def save_settings(self): if field and field != current_bw_dir: ab_settings.custom_bw_dir = field ab_settings.current_bw_dir = field - print("Saved startup brightway directory as: ", field) + log.info("Saved startup brightway directory as: ", field) # project field_project = self.field("startup_project") @@ -38,13 +44,13 @@ def save_settings(self): if field_project and field_project != current_startup_project: new_startup_project = field_project ab_settings.startup_project = new_startup_project - print("Saved startup project as: ", new_startup_project) + log.info("Saved startup project as: ", new_startup_project) ab_settings.write_settings() signals.switch_bw2_dir_path.emit(field) def cancel(self): - print("Going back to before settings were changed.") + log.info("Going back to before settings were changed.") if bw.projects._base_data_dir != self.last_bwdir: signals.switch_bw2_dir_path.emit(self.last_bwdir) signals.change_project.emit(self.last_project) # project changes only if directory is changed @@ -220,7 +226,7 @@ def update_project_combo(self, initialization: bool = True, path: str = None): if self.project_names: self.startup_project_combobox.addItems(self.project_names) else: - print("Warning: No projects found in this directory.") + log.warning("No projects found in this directory.") # return if ab_settings.startup_project in self.project_names: self.startup_project_combobox.setCurrentText(ab_settings.startup_project) diff --git a/activity_browser/ui/wizards/uncertainty.py b/activity_browser/ui/wizards/uncertainty.py index 038068b77..4c27550d7 100644 --- a/activity_browser/ui/wizards/uncertainty.py +++ b/activity_browser/ui/wizards/uncertainty.py @@ -11,6 +11,12 @@ from ...bwutils.uncertainty import EMPTY_UNCERTAINTY from ...signals import signals +import logging +from activity_browser.logger import ABHandler + +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger) + class UncertaintyWizard(QtWidgets.QWizard): """Using this wizard, guide the user through selecting an 'uncertainty' @@ -573,7 +579,7 @@ def initializePage(self): matrix = PedigreeMatrix.from_dict(obj.uncertainty.get("pedigree", {})) self.pedigree = matrix.factors except AssertionError as e: - print("Could not extract pedigree data: {}".format(str(e))) + log.info("Could not extract pedigree data: {}".format(str(e))) self.pedigree = {} self.check_complete() diff --git a/pytest.ini b/pytest.ini index e43dc27cb..c13c3f06a 100644 --- a/pytest.ini +++ b/pytest.ini @@ -1,3 +1,4 @@ [pytest] testpaths=tests qt_api=pyside2 +log_cli=true diff --git a/run-activity-browser.py b/run-activity-browser.py index de81f5c4b..5a07f126e 100644 --- a/run-activity-browser.py +++ b/run-activity-browser.py @@ -1,5 +1,13 @@ # -*- coding: utf-8 -*- +import logging + +from activity_browser.logger import ABHandler + from activity_browser import run_activity_browser +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, __name__) +log.info("The Activity-Browser log file can be found at {}".format(log.log_file_path())) + run_activity_browser() \ No newline at end of file diff --git a/tests/pytest.ini b/tests/pytest.ini new file mode 100644 index 000000000..7c658ea19 --- /dev/null +++ b/tests/pytest.ini @@ -0,0 +1,4 @@ +[pytest] +testpaths=tests +qt_api=pyside2 +log_level=INFO diff --git a/tests/test_uncertainty_wizard.py b/tests/test_uncertainty_wizard.py index 1797a5191..6d5ba710c 100644 --- a/tests/test_uncertainty_wizard.py +++ b/tests/test_uncertainty_wizard.py @@ -1,6 +1,8 @@ # -*- coding: utf-8 -*- +import logging import sys + from bw2data.parameters import ProjectParameter import numpy as np from PySide2.QtWidgets import QMessageBox, QWizard @@ -13,10 +15,18 @@ from activity_browser.ui.wizards import UncertaintyWizard from activity_browser.signals import signals +from activity_browser.logger import ABHandler + """ Mess around with the uncertainty wizard. """ +logger = logging.getLogger('ab_logs') +log = ABHandler.setup_with_logger(logger, "uncertainty_wizard_test") + +log.setLevel(logging.INFO, True) +log.propagate = True + @pytest.mark.skipif(sys.platform=='darwin', reason="tests segfaults on osx") def test_wizard_fail(qtbot): """Can't create a wizard if no uncertainty interface exists.""" @@ -26,8 +36,9 @@ def test_wizard_fail(qtbot): @pytest.mark.skipif(sys.platform=='darwin', reason="tests segfaults on osx") -def test_uncertainty_wizard_simple(qtbot, bw2test, capsys): +def test_uncertainty_wizard_simple(qtbot, bw2test, caplog): """Use extremely simple text to open the wizard and go to all the pages.""" + caplog.set_level(logging.INFO) param = ProjectParameter.create(name="test1", amount=3) wizard = UncertaintyWizard(param, None) qtbot.addWidget(wizard) @@ -42,8 +53,8 @@ def test_uncertainty_wizard_simple(qtbot, bw2test, capsys): wizard.type.pedigree.click() # Pedigree is empty, so complaint is issued. - captured = capsys.readouterr() - assert "Could not extract pedigree data" in captured.out + captured = caplog.text + assert "Could not extract pedigree data" in captured # Now go back for giggles. with qtbot.waitSignal(wizard.currentIdChanged, timeout=100):