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

@@ -16,4 +16,6 @@ activity_browser/ABSettings.json
 *.bak
 /.idea
 /.vscode
-.coverage
+.coverage
+.logs
+test/.logs

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
 

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()

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
 
 

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
         ))

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]))
+#    print(mc.get_results_dataframe(method=mc.methods[0]))
+#    print(mc.get_results_dataframe(act_key=mc.activity_keys[0]))

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
 

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