Replace print with logging

bw2data/backends/base.py

@@ -44,6 +44,7 @@
 from bw2data.query import Query
 from bw2data.search import IndexManager, Searcher
 from bw2data.utils import as_uncertainty_dict, get_geocollection, get_node, set_correct_process_type
+from bw2data.logs import stdout_feedback_logger
 
 _VALID_KEYS = {"location", "name", "product", "type"}
 
@@ -420,8 +421,7 @@ def _get_queryset(self, random=False, filters=True):
                 for key, value in filters.items():
                     qs = qs.where(getattr(ActivityDataset, key) == value)
             if self.filters:
-                print("Using the following database filters:")
-                pprint.pprint(self.filters)
+                stdout_feedback_logger.info("Using the following database filters: %s", pprint.pformat(self.filters))
                 for key, value in self.filters.items():
                     qs = qs.where(getattr(ActivityDataset, key) == value)
         if self.order_by and not random:
@@ -437,7 +437,7 @@ def _set_filters(self, filters):
         if not filters:
             self._filters = {}
         else:
-            print("Filters will effect all database queries" " until unset (`.filters = None`)")
+            stdout_feedback_logger.info("Filters will effect all database queries" " until unset (`.filters = None`)")
             assert isinstance(filters, dict), "Filter must be a dictionary"
             for key in filters:
                 assert key in _VALID_KEYS, "Filter key {} is invalid".format(key)
@@ -625,7 +625,7 @@ def merger(d1: dict, d2: dict) -> dict:
             if dataset.get("type") in labels.process_node_types
         }
         if None in geocollections:
-            print(
+            stdout_feedback_logger.warning(
                 "Not able to determine geocollections for all datasets. This database is not ready for regionalization."
             )
             geocollections.discard(None)
@@ -719,7 +719,7 @@ def make_searchable(self, reset=False):
         if self.name not in databases:
             raise UnknownObject("This database is not yet registered")
         if self._searchable and not reset:
-            print("This database is already searchable")
+            stdout_feedback_logger.info("This database is already searchable")
             return
         databases[self.name]["searchable"] = True
         databases.flush()
@@ -964,7 +964,7 @@ def set_geocollections(self):
             if x.get("type") in labels.process_node_types
         }
         if None in geocollections:
-            print(
+            stdout_feedback_logger.warning(
                 "Not able to determine geocollections for all datasets. Not setting `geocollections`."
             )
             geocollections.discard(None)
@@ -1003,7 +1003,7 @@ def get_uniqueness_key(exchange, fields):
         for lst in exchange_mapping.values():
             if len(lst) > 1:
                 for exc in lst[-1:0:-1]:
-                    print("Deleting exchange:", exc)
+                    stdout_feedback_logger.warning("Deleting exchange: %s", exc)
                     exc.delete()
 
     def nodes_to_dataframe(
@@ -1102,7 +1102,7 @@ def edges_to_dataframe(
                         func(node=target, edge=edge, row=row)
                 result.append(row)
 
-        print("Creating DataFrame")
+        stdout_feedback_logger.info("Creating DataFrame")
         df = pandas.DataFrame(result)
 
         if categorical:
@@ -1122,7 +1122,7 @@ def edges_to_dataframe(
                 "source_categories",
                 "edge_type",
             ]
-            print("Compressing DataFrame")
+            stdout_feedback_logger.info("Compressing DataFrame")
             for column in categorical_columns:
                 if column in df.columns:
                     df[column] = df[column].astype("category")

bw2data/backends/iotable/backend.py

@@ -10,6 +10,7 @@
 from bw2data.backends import SQLiteBackend
 from bw2data.backends.iotable.proxies import IOTableActivity, IOTableExchanges
 from bw2data.configuration import labels
+from bw2data.logs import stdout_feedback_logger
 
 
 class IOTableBackend(SQLiteBackend):
@@ -34,7 +35,7 @@ def write_exchanges(self, technosphere, biosphere, dependents):
         Technosphere and biosphere data has format ``(row id, col id, value, flip)``.
 
         """
-        print("Starting IO table write")
+        stdout_feedback_logger.info("Starting IO table write")
 
         # create empty datapackage
         dp = create_datapackage(
@@ -59,7 +60,7 @@ def write_exchanges(self, technosphere, biosphere, dependents):
             nrows=len(self),
         )
 
-        print("Adding technosphere matrix")
+        stdout_feedback_logger.info("Adding technosphere matrix")
         # if technosphere is a dictionary pass it's keys & values
         if isinstance(technosphere, dict):
             dp.add_persistent_vector(
@@ -77,7 +78,7 @@ def write_exchanges(self, technosphere, biosphere, dependents):
         else:
             raise Exception(f"Error: Unsupported technosphere type: {type(technosphere)}")
 
-        print("Adding biosphere matrix")
+        stdout_feedback_logger.info("Adding biosphere matrix")
         # if biosphere is a dictionary pass it's keys & values
         if isinstance(biosphere, dict):
             dp.add_persistent_vector(
@@ -96,7 +97,7 @@ def write_exchanges(self, technosphere, biosphere, dependents):
             raise Exception(f"Error: Unsupported biosphere type: {type(technosphere)}")
 
         # finalize
-        print("Finalizing serialization")
+        stdout_feedback_logger.info("Finalizing serialization")
         dp.finalize_serialization()
 
         databases[self.name]["depends"] = sorted(set(dependents).difference({self.name}))
@@ -142,7 +143,7 @@ def edges_to_dataframe(self) -> pd.DataFrame:
         def cached_lookup(id_):
             return get_node(id=id_)
 
-        print("Retrieving metadata")
+        stdout_feedback_logger.info("Retrieving metadata")
         activities = {o.id: o for o in self}
 
         def get(id_):
@@ -189,7 +190,7 @@ def get_edge_types(exchanges):
 
             return np.hstack(arrays)
 
-        print("Loading datapackage")
+        stdout_feedback_logger.info("Loading datapackage")
         exchanges = IOTableExchanges(datapackage=self.datapackage())
 
         target_ids = np.hstack(
@@ -201,11 +202,11 @@ def get_edge_types(exchanges):
         edge_amounts = np.hstack([resource["data"]["array"] for resource in exchanges.resources])
         edge_types = get_edge_types(exchanges)
 
-        print("Creating metadata dataframes")
+        stdout_feedback_logger.info("Creating metadata dataframes")
         target_metadata = metadata_dataframe(target_ids)
         source_metadata = metadata_dataframe(source_ids, "source_")
 
-        print("Building merged dataframe")
+        stdout_feedback_logger.info("Building merged dataframe")
         df = pd.DataFrame(
             {
                 "target_id": target_ids,
@@ -233,7 +234,7 @@ def get_edge_types(exchanges):
             "source_categories",
             "edge_type",
         ]
-        print("Compressing DataFrame")
+        stdout_feedback_logger.info("Compressing DataFrame")
         for column in categorical_columns:
             if column in df.columns:
                 df[column] = df[column].astype("category")

bw2data/backends/proxies.py

@@ -19,6 +19,7 @@
 from bw2data.errors import ValidityError
 from bw2data.proxies import ActivityProxyBase, ExchangeProxyBase
 from bw2data.search import IndexManager
+from bw2data.logs import stdout_feedback_logger
 
 
 class Exchanges(Iterable):
@@ -238,10 +239,10 @@ def __setitem__(self, key, value):
             raise ValueError("`id` is read-only")
         elif key == "code" and "code" in self._data:
             self._change_code(value)
-            print("Successfully switched activity dataset to new code `{}`".format(value))
+            stdout_feedback_logger.info("Successfully switched activity dataset to new code `%s`", value)
         elif key == "database" and "database" in self._data:
             self._change_database(value)
-            print("Successfully switch activity dataset to database `{}`".format(value))
+            stdout_feedback_logger.info("Successfully switch activity dataset to database `%s`", value)
         else:
             super(Activity, self).__setitem__(key, value)
 

bw2data/backends/utils.py

@@ -29,7 +29,7 @@ def convert_backend(database_name, backend):
     Returns `False` if the old and new backend are the same. Otherwise returns an instance of the new Database object.
     """
     if database_name not in databases:
-        print("Can't find database {}".format(database_name))
+        raise ValueError(f"Can't find database {database_name}")
 
     from bw2data.database import Database
 

bw2data/backends/wurst_extraction.py

@@ -5,6 +5,7 @@
 from bw2data.backends import ActivityDataset, ExchangeDataset, SQLiteBackend
 from bw2data.configuration import labels
 from bw2data.database import DatabaseChooser
+from bw2data.logs import stdout_feedback_logger
 
 
 def _list_or_dict(obj):
@@ -159,13 +160,13 @@ def extract_brightway_databases(database_names, add_properties=False, add_identi
     exchange_qs = ExchangeDataset.select().where(ExchangeDataset.output_database << database_names)
 
     # Retrieve all activity data
-    print("Getting activity data")
+    stdout_feedback_logger.info("Getting activity data")
     activities = [extract_activity(o, add_identifiers=add_identifiers) for o in tqdm(activity_qs)]
     # Add each exchange to the activity list of exchanges
-    print("Adding exchange data to activities")
+    stdout_feedback_logger.info("Adding exchange data to activities")
     add_exchanges_to_consumers(activities, exchange_qs, add_properties)
     # Add details on exchanges which come from our databases
-    print("Filling out exchange data")
+    stdout_feedback_logger.info("Filling out exchange data")
     add_input_info_for_indigenous_exchanges(
         activities, database_names, add_identifiers=add_identifiers
     )

bw2data/data_store.py

@@ -11,6 +11,7 @@
 from bw2data import projects
 from bw2data.errors import MissingIntermediateData, UnknownObject
 from bw2data.fatomic import open as atomic_open
+from bw2data.logs import stdout_feedback_logger
 
 
 class DataStore:
@@ -117,7 +118,7 @@ def backup(self):
 
             return BW2Package.export_obj(self)
         except ImportError:
-            print("bw2io not installed")
+            stdout_feedback_logger.warning("bw2io not installed")
 
     def write(self, data):
         """Serialize intermediate data to disk.

bw2data/logs.py

@@ -1,11 +1,11 @@
+from logging.handlers import RotatingFileHandler
 import codecs
 import datetime
 import logging
-import uuid
-from logging.handlers import RotatingFileHandler
+import sys
+import os
 
-from bw2data import config, projects
-from bw2data.utils import create_in_memory_zipfile_from_directory, random_string
+import structlog
 
 try:
     import anyjson
@@ -24,6 +24,8 @@ def __getattr__(self, attr):
 
 
 def get_logger(name, level=logging.INFO):
+    from bw2data import projects
+
     filename = "{}-{}.log".format(
         name,
         datetime.datetime.now().strftime("%d-%B-%Y-%I-%M%p"),
@@ -43,8 +45,44 @@ def get_logger(name, level=logging.INFO):
     return logger
 
 
+def get_stdout_feedback_logger(name: str, level: int = logging.INFO):
+    logger = logging.getLogger(name)
+    logger.propagate = False
+    logger.setLevel(level)
+    handler = logging.StreamHandler(sys.stdout)
+    formatter = logging.Formatter('%(asctime)s - %(levelname)s - %(message)s', "%H:%M:%S%z")
+    handler.setFormatter(formatter)
+    logger.addHandler(handler)
+    return logger
+
+
+def get_structlog_stdout_feedback_logger(level: int = logging.INFO):
+    structlog.reset_defaults()
+    structlog.configure(
+        processors=[
+            structlog.contextvars.merge_contextvars,
+            structlog.processors.add_log_level,
+            structlog.processors.StackInfoRenderer(),
+            structlog.dev.set_exc_info,
+            structlog.processors.TimeStamper(fmt="%H:%M:%S%z", utc=False),
+            structlog.dev.ConsoleRenderer()
+        ],
+        wrapper_class=structlog.make_filtering_bound_logger(level),
+        context_class=dict,
+        logger_factory=structlog.PrintLoggerFactory(),
+        cache_logger_on_first_use=True
+    )
+    logger = structlog.get_logger()
+    logger.debug("Starting feedback logger")
+    structlog.reset_defaults()
+    return logger
+
+
 def get_io_logger(name):
     """Build a logger that records only relevent data for display later as HTML."""
+    from bw2data import projects
+    from bw2data.utils import random_string
+
     filepath = projects.logs_dir / "{}.{}.log".format(name, random_string(6))
     handler = logging.StreamHandler(codecs.open(filepath, "w", "utf-8"))
     logger = logging.getLogger(name)
@@ -56,6 +94,8 @@ def get_io_logger(name):
 
 
 def get_verbose_logger(name, level=logging.WARNING):
+    from bw2data import projects
+
     filename = "{}-{}.log".format(
         name,
         datetime.datetime.now().strftime("%d-%B-%Y-%I-%M%p"),
@@ -93,3 +133,9 @@ def close_log(log):
     for handler in handlers:
         handler.close()
         log.removeHandler(handler)
+
+
+if os.getenv("BRIGHTWAY_NO_STRUCTLOG"):
+    stdout_feedback_logger = get_stdout_feedback_logger("brightway-stdout-feedback")
+else:
+    stdout_feedback_logger = get_structlog_stdout_feedback_logger()

bw2data/project.py

@@ -16,6 +16,7 @@
 from bw2data.signals import project_changed, project_created
 from bw2data.sqlite import PickleField, SubstitutableDatabase
 from bw2data.utils import maybe_path
+from bw2data.logs import stdout_feedback_logger
 
 READ_ONLY_PROJECT = """
 ***Read only project***
@@ -77,7 +78,7 @@ def __init__(self):
 
             MIGRATION_WARNING = """Adding a column to the projects database. A backup copy of this database '{}' was made at '{}'; if you have problems, file an issue, and restore the backup data to use the stable version of Brightway2."""
 
-            print(MIGRATION_WARNING.format(src_filepath, backup_filepath))
+            stdout_feedback_logger.warning(MIGRATION_WARNING.format(src_filepath, backup_filepath))
 
             ADD_FULL_HASH_COLUMN = (
                 """ALTER TABLE projectdataset ADD COLUMN "full_hash" integer default 1"""
@@ -135,7 +136,7 @@ def _get_base_directories(self):
                     )
                 )
             else:
-                print(
+                stdout_feedback_logger.info(
                     "Using environment variable BRIGHTWAY2_DIR for data "
                     "directory:\n{}".format(envvar)
                 )
@@ -208,7 +209,7 @@ def _do_automatic_updates(self):
         from bw2data.updates import Updates
 
         for update_name in Updates.check_automatic_updates():
-            print("Applying automatic update: {}".format(update_name))
+            stdout_feedback_logger.info("Applying automatic update: {}".format(update_name))
             Updates.do_update(update_name)
 
     def _reset_meta(self):

bw2data/sqlite.py

@@ -3,6 +3,8 @@
 
 from peewee import BlobField, SqliteDatabase, TextField
 
+from bw2data.logs import stdout_feedback_logger
+
 
 class PickleField(BlobField):
     def db_value(self, value):
@@ -45,7 +47,7 @@ def transaction(self):
         return self.db.transaction()
 
     def vacuum(self):
-        print("Vacuuming database ")
+        stdout_feedback_logger.info("Vacuuming database ")
         self.execute_sql("VACUUM;")