Moving away from using the root logger everywhere

superset/cli.py

@@ -33,6 +33,8 @@
 from superset.extensions import celery_app, db
 from superset.utils import core as utils
 
+logger = logging.getLogger(__name__)
+
 
 @click.group(cls=FlaskGroup, create_app=create_app)
 @with_appcontext
@@ -180,7 +182,7 @@ def refresh_druid(datasource, merge):
             cluster.refresh_datasources(datasource_name=datasource, merge_flag=merge)
         except Exception as e:  # pylint: disable=broad-except
             print("Error while processing cluster '{}'\n{}".format(cluster, str(e)))
-            logging.exception(e)
+            logger.exception(e)
         cluster.metadata_last_refreshed = datetime.now()
         print("Refreshed metadata from cluster " "[" + cluster.cluster_name + "]")
     session.commit()
@@ -222,13 +224,13 @@ def import_dashboards(path, recursive, username):
     if username is not None:
         g.user = security_manager.find_user(username=username)
     for file_ in files:
-        logging.info("Importing dashboard from file %s", file_)
+        logger.info("Importing dashboard from file %s", file_)
         try:
             with file_.open() as data_stream:
                 dashboard_import_export.import_dashboards(db.session, data_stream)
         except Exception as e:  # pylint: disable=broad-except
-            logging.error("Error when importing dashboard from file %s", file_)
-            logging.error(e)
+            logger.error("Error when importing dashboard from file %s", file_)
+            logger.error(e)
 
 
 @superset.command()
@@ -247,7 +249,7 @@ def export_dashboards(print_stdout, dashboard_file):
     if print_stdout or not dashboard_file:
         print(data)
     if dashboard_file:
-        logging.info("Exporting dashboards to %s", dashboard_file)
+        logger.info("Exporting dashboards to %s", dashboard_file)
         with open(dashboard_file, "w") as data_stream:
             data_stream.write(data)
 
@@ -292,15 +294,15 @@ def import_datasources(path, sync, recursive):
         files.extend(path_object.rglob("*.yaml"))
         files.extend(path_object.rglob("*.yml"))
     for file_ in files:
-        logging.info("Importing datasources from file %s", file_)
+        logger.info("Importing datasources from file %s", file_)
         try:
             with file_.open() as data_stream:
                 dict_import_export.import_from_dict(
                     db.session, yaml.safe_load(data_stream), sync=sync_array
                 )
         except Exception as e:  # pylint: disable=broad-except
-            logging.error("Error when importing datasources from file %s", file_)
-            logging.error(e)
+            logger.error("Error when importing datasources from file %s", file_)
+            logger.error(e)
 
 
 @superset.command()
@@ -340,7 +342,7 @@ def export_datasources(
     if print_stdout or not datasource_file:
         yaml.safe_dump(data, stdout, default_flow_style=False)
     if datasource_file:
-        logging.info("Exporting datasources to %s", datasource_file)
+        logger.info("Exporting datasources to %s", datasource_file)
         with open(datasource_file, "w") as data_stream:
             yaml.safe_dump(data, data_stream, default_flow_style=False)
 
@@ -389,7 +391,7 @@ def update_datasources_cache():
 )
 def worker(workers):
     """Starts a Superset worker for async SQL query execution."""
-    logging.info(
+    logger.info(
         "The 'superset worker' command is deprecated. Please use the 'celery "
         "worker' command instead."
     )
@@ -424,7 +426,7 @@ def flower(port, address):
         f"--port={port} "
         f"--address={address} "
     )
-    logging.info(
+    logger.info(
         "The 'superset flower' command is deprecated. Please use the 'celery "
         "flower' command instead."
     )

superset/common/query_context.py

@@ -33,6 +33,7 @@
 
 config = app.config
 stats_logger: BaseStatsLogger = config["STATS_LOGGER"]
+logger = logging.getLogger(__name__)
 
 
 class QueryContext:
@@ -175,7 +176,7 @@ def get_df_payload(  # pylint: disable=too-many-locals,too-many-statements
     ) -> Dict[str, Any]:
         """Handles caching around the df payload retrieval"""
         cache_key = self.cache_key(query_obj, **kwargs)
-        logging.info("Cache key: %s", cache_key)
+        logger.info("Cache key: %s", cache_key)
         is_loaded = False
         stacktrace = None
         df = pd.DataFrame()
@@ -196,11 +197,11 @@ def get_df_payload(  # pylint: disable=too-many-locals,too-many-statements
                     is_loaded = True
                     stats_logger.incr("loaded_from_cache")
                 except Exception as e:  # pylint: disable=broad-except
-                    logging.exception(e)
-                    logging.error(
+                    logger.exception(e)
+                    logger.error(
                         "Error reading cache: %s", utils.error_msg_from_exception(e)
                     )
-                logging.info("Serving from cache")
+                logger.info("Serving from cache")
 
         if query_obj and not is_loaded:
             try:
@@ -213,7 +214,7 @@ def get_df_payload(  # pylint: disable=too-many-locals,too-many-statements
                     stats_logger.incr("loaded_from_source")
                     is_loaded = True
             except Exception as e:  # pylint: disable=broad-except
-                logging.exception(e)
+                logger.exception(e)
                 if not error_message:
                     error_message = "{}".format(e)
                 status = utils.QueryStatus.FAILED
@@ -224,7 +225,7 @@ def get_df_payload(  # pylint: disable=too-many-locals,too-many-statements
                     cache_value = dict(dttm=cached_dttm, df=df, query=query)
                     cache_binary = pkl.dumps(cache_value, protocol=pkl.HIGHEST_PROTOCOL)
 
-                    logging.info(
+                    logger.info(
                         "Caching %d chars at key %s", len(cache_binary), cache_key
                     )
 
@@ -233,8 +234,8 @@ def get_df_payload(  # pylint: disable=too-many-locals,too-many-statements
                 except Exception as e:  # pylint: disable=broad-except
                     # cache.set call can fail if the backend is down or if
                     # the key is too large or whatever other reasons
-                    logging.warning("Could not cache key %s", cache_key)
-                    logging.exception(e)
+                    logger.warning("Could not cache key %s", cache_key)
+                    logger.exception(e)
                     cache.delete(cache_key)
         return {
             "cache_key": cache_key,

superset/config.py

@@ -39,6 +39,9 @@
 from superset.utils.log import DBEventLogger
 from superset.utils.logging_configurator import DefaultLoggingConfigurator
 
+logger = logging.getLogger(__name__)
+
+
 # Realtime stats logger, a StatsD implementation exists
 STATS_LOGGER = DummyStatsLogger()
 EVENT_LOGGER = DBEventLogger()
@@ -773,7 +776,7 @@ class CeleryConfig:  # pylint: disable=too-few-public-methods
 
         print(f"Loaded your LOCAL configuration at [{cfg_path}]")
     except Exception:
-        logging.exception(
+        logger.exception(
             f"Failed to import config for {CONFIG_PATH_ENV_VAR}={cfg_path}"
         )
         raise
@@ -784,5 +787,5 @@ class CeleryConfig:  # pylint: disable=too-few-public-methods
 
         print(f"Loaded your LOCAL configuration at [{superset_config.__file__}]")
     except Exception:
-        logging.exception("Found but failed to import local superset_config")
+        logger.exception("Found but failed to import local superset_config")
         raise

superset/connectors/druid/models.py

@@ -87,6 +87,7 @@
 DRUID_TZ = conf.get("DRUID_TZ")
 POST_AGG_TYPE = "postagg"
 metadata = Model.metadata  # pylint: disable=no-member
+logger = logging.getLogger(__name__)
 
 try:
     # Postaggregator might not have been imported.
@@ -628,7 +629,7 @@ def lookup_cluster(d: DruidDatasource) -> Optional[DruidCluster]:
 
     def latest_metadata(self):
         """Returns segment metadata from the latest segment"""
-        logging.info("Syncing datasource [{}]".format(self.datasource_name))
+        logger.info("Syncing datasource [{}]".format(self.datasource_name))
         client = self.cluster.get_pydruid_client()
         try:
             results = client.time_boundary(datasource=self.datasource_name)
@@ -657,8 +658,8 @@ def latest_metadata(self):
                 analysisTypes=[],
             )
         except Exception as e:
-            logging.warning("Failed first attempt to get latest segment")
-            logging.exception(e)
+            logger.warning("Failed first attempt to get latest segment")
+            logger.exception(e)
         if not segment_metadata:
             # if no segments in the past 7 days, look at all segments
             lbound = datetime(1901, 1, 1).isoformat()[:10]
@@ -674,8 +675,8 @@ def latest_metadata(self):
                     analysisTypes=[],
                 )
             except Exception as e:
-                logging.warning("Failed 2nd attempt to get latest segment")
-                logging.exception(e)
+                logger.warning("Failed 2nd attempt to get latest segment")
+                logger.exception(e)
         if segment_metadata:
             return segment_metadata[-1]["columns"]
 
@@ -963,7 +964,7 @@ def metrics_and_post_aggs(
 
     def values_for_column(self, column_name: str, limit: int = 10000) -> List:
         """Retrieve some values for the given column"""
-        logging.info(
+        logger.info(
             "Getting values for columns [{}] limited to [{}]".format(column_name, limit)
         )
         # TODO: Use Lexicographic TopNMetricSpec once supported by PyDruid
@@ -1223,12 +1224,12 @@ def run_query(  # druid
             qry["limit"] = row_limit
             client.scan(**qry)
         elif len(groupby) == 0 and not having_filters:
-            logging.info("Running timeseries query for no groupby values")
+            logger.info("Running timeseries query for no groupby values")
             del qry["dimensions"]
             client.timeseries(**qry)
         elif not having_filters and len(groupby) == 1 and order_desc:
             dim = list(qry["dimensions"])[0]
-            logging.info("Running two-phase topn query for dimension [{}]".format(dim))
+            logger.info("Running two-phase topn query for dimension [{}]".format(dim))
             pre_qry = deepcopy(qry)
             if timeseries_limit_metric:
                 order_by = utils.get_metric_name(timeseries_limit_metric)
@@ -1253,7 +1254,7 @@ def run_query(  # druid
             del pre_qry["dimensions"]
 
             client.topn(**pre_qry)
-            logging.info("Phase 1 Complete")
+            logger.info("Phase 1 Complete")
             if phase == 2:
                 query_str += "// Two phase query\n// Phase 1\n"
             query_str += json.dumps(
@@ -1276,13 +1277,13 @@ def run_query(  # druid
             del qry["dimensions"]
             qry["metric"] = list(qry["aggregations"].keys())[0]
             client.topn(**qry)
-            logging.info("Phase 2 Complete")
+            logger.info("Phase 2 Complete")
         elif len(groupby) > 0 or having_filters:
             # If grouping on multiple fields or using a having filter
             # we have to force a groupby query
-            logging.info("Running groupby query for dimensions [{}]".format(dimensions))
+            logger.info("Running groupby query for dimensions [{}]".format(dimensions))
             if timeseries_limit and is_timeseries:
-                logging.info("Running two-phase query for timeseries")
+                logger.info("Running two-phase query for timeseries")
 
                 pre_qry = deepcopy(qry)
                 pre_qry_dims = self._dimensions_to_values(qry["dimensions"])
@@ -1324,7 +1325,7 @@ def run_query(  # druid
                     "columns": [{"dimension": order_by, "direction": order_direction}],
                 }
                 client.groupby(**pre_qry)
-                logging.info("Phase 1 Complete")
+                logger.info("Phase 1 Complete")
                 query_str += "// Two phase query\n// Phase 1\n"
                 query_str += json.dumps(
                     client.query_builder.last_query.query_dict, indent=2
@@ -1357,7 +1358,7 @@ def run_query(  # druid
                     ],
                 }
             client.groupby(**qry)
-            logging.info("Query Complete")
+            logger.info("Query Complete")
         query_str += json.dumps(client.query_builder.last_query.query_dict, indent=2)
         return query_str
 

superset/connectors/druid/views.py

@@ -45,6 +45,8 @@
 
 from . import models
 
+logger = logging.getLogger(__name__)
+
 
 class DruidColumnInlineView(CompactCRUDMixin, SupersetModelView):
     datamodel = SQLAInterface(models.DruidColumn)
@@ -380,7 +382,7 @@ def refresh_datasources(self, refresh_all=True):
                     ),
                     "danger",
                 )
-                logging.exception(e)
+                logger.exception(e)
                 pass
             if valid_cluster:
                 cluster.metadata_last_refreshed = datetime.now()

superset/connectors/sqla/models.py

@@ -62,6 +62,7 @@
 
 config = app.config
 metadata = Model.metadata  # pylint: disable=no-member
+logger = logging.getLogger(__name__)
 
 
 class SqlaQuery(NamedTuple):
@@ -98,7 +99,7 @@ def query(self, query_obj: Dict[str, Any]) -> QueryResult:
         except Exception as e:
             df = pd.DataFrame()
             status = utils.QueryStatus.FAILED
-            logging.exception(e)
+            logger.exception(e)
             error_message = utils.error_msg_from_exception(e)
         return QueryResult(
             status=status, df=df, duration=0, query="", error_message=error_message
@@ -590,7 +591,7 @@ def get_template_processor(self, **kwargs):
     def get_query_str_extended(self, query_obj: Dict[str, Any]) -> QueryStringExtended:
         sqlaq = self.get_sqla_query(**query_obj)
         sql = self.database.compile_sqla_query(sqlaq.sqla_query)
-        logging.info(sql)
+        logger.info(sql)
         sql = sqlparse.format(sql, reindent=True)
         sql = self.mutate_query_from_config(sql)
         return QueryStringExtended(
@@ -1005,7 +1006,7 @@ def mutator(df: pd.DataFrame) -> None:
         except Exception as e:
             df = pd.DataFrame()
             status = utils.QueryStatus.FAILED
-            logging.exception(f"Query {sql} on schema {self.schema} failed")
+            logger.exception(f"Query {sql} on schema {self.schema} failed")
             db_engine_spec = self.database.db_engine_spec
             error_message = db_engine_spec.extract_error_message(e)
 
@@ -1025,7 +1026,7 @@ def fetch_metadata(self) -> None:
         try:
             table = self.get_sqla_table_object()
         except Exception as e:
-            logging.exception(e)
+            logger.exception(e)
             raise Exception(
                 _(
                     "Table [{}] doesn't seem to exist in the specified database, "
@@ -1052,8 +1053,8 @@ def fetch_metadata(self) -> None:
                 )
             except Exception as e:
                 datatype = "UNKNOWN"
-                logging.error("Unrecognized data type in {}.{}".format(table, col.name))
-                logging.exception(e)
+                logger.error("Unrecognized data type in {}.{}".format(table, col.name))
+                logger.exception(e)
             dbcol = dbcols.get(col.name, None)
             if not dbcol:
                 dbcol = TableColumn(column_name=col.name, type=datatype)