Merge pull request #338 from jenshnielsen/improve_logging

Improvements to logging

plottr/apps/autoplot.py

@@ -34,11 +34,7 @@
 
 # TODO: * separate logging window
 
-
-def logger() -> logging.Logger:
-    logger = logging.getLogger('plottr.apps.autoplot')
-    logger.setLevel(plottrlog.LEVEL)
-    return logger
+LOGGER = logging.getLogger('plottr.apps.autoplot')
 
 
 def autoplot(inputData: Union[None, DataDictBase] = None,
@@ -103,7 +99,7 @@ def monitorTriggered(self) -> None:
         Is called whenever the monitor timer triggers, and emit the
         :attr:`trigger` Signal.
         """
-        logger().debug('Emit trigger')
+        LOGGER.debug('Emit trigger')
         self.trigger.emit()
 
     @Slot(float)
@@ -227,7 +223,7 @@ def setInput(self, data: DataDictBase, resetDefaults: bool = True) -> None:
         defined.
         """
         if self.loaderNode is not None:
-            logger().warning("A loader node is defined. Use that for inserting data.")
+            LOGGER.warning("A loader node is defined. Use that for inserting data.")
         else:
             self.fc.setInput(dataIn=data)
             if resetDefaults or not self._initialized:

plottr/apps/inspectr.py

@@ -37,10 +37,7 @@
 __author__ = 'Wolfgang Pfaff'
 __license__ = 'MIT'
 
-
-def logger() -> logging.Logger:
-    logger = plottrlog.getLogger('plottr.apps.inspectr')
-    return logger
+LOGGER = plottrlog.getLogger('plottr.apps.inspectr')
 
 
 ### Database inspector tool
@@ -478,7 +475,7 @@ def loadDB(self) -> None:
             )
 
         if path:
-            logger().info(f"Opening: {path}")
+            LOGGER.info(f"Opening: {path}")
             self.loadFullDB(path=path)
 
     def loadFullDB(self, path: Optional[str] = None) -> None:
@@ -495,12 +492,12 @@ def loadFullDB(self, path: Optional[str] = None) -> None:
 
     def DBLoaded(self, dbdf: pandas.DataFrame) -> None:
         if self.dbdf is not None and dbdf.equals(self.dbdf):
-            logger().debug('DB reloaded with no changes. Skipping update')
+            LOGGER.debug('DB reloaded with no changes. Skipping update')
             return None
         self.dbdf = dbdf
         self.dbdfUpdated.emit()
         self.dateList.sendSelectedDates()
-        logger().debug('DB reloaded')
+        LOGGER.debug('DB reloaded')
 
         if self.latestRunId is not None:
             idxs = self.dbdf.index.values
@@ -543,7 +540,7 @@ def setMonitorInterval(self, val: float) -> None:
 
     @Slot()
     def monitorTriggered(self) -> None:
-        logger().debug('Refreshing DB')
+        LOGGER.debug('Refreshing DB')
         self.refreshDB()
 
     @Slot()
@@ -652,9 +649,9 @@ def inspectr(dbPath: Optional[str] = None) -> QCodesDBInspector:
     return win
 
 
-def main(dbPath: Optional[str]) -> None:
+def main(dbPath: Optional[str], log_level: Union[int, str] = logging.WARNING) -> None:
     app = QtWidgets.QApplication([])
-    plottrlog.enableStreamHandler(True)
+    plottrlog.enableStreamHandler(True, log_level)
 
     win = inspectr(dbPath=dbPath)
     win.show()
@@ -669,5 +666,8 @@ def script() -> None:
     parser = argparse.ArgumentParser(description='inspectr -- sifting through qcodes data.')
     parser.add_argument('--dbpath', help='path to qcodes .db file',
                         default=None)
+    parser.add_argument("--console-log-level",
+                        choices=("ERROR", "WARNING", "INFO", "DEBUG"),
+                        default="WARNING")
     args = parser.parse_args()
-    main(args.dbpath)
+    main(args.dbpath, args.console_log_level)

plottr/log.py

@@ -26,7 +26,6 @@
     logging.DEBUG : QtGui.QColor('gray'),
     }
 
-LEVEL = logging.INFO
 
 class QLogHandler(logging.Handler):
 
@@ -62,6 +61,7 @@ def __init__(self, parent: Optional[QtWidgets.QWidget] = None,
             )
         logTextBox = QLogHandler(self)
         logTextBox.setFormatter(fmt)
+        logTextBox.setLevel(level)
 
         # make the widget
         layout = QtWidgets.QVBoxLayout()
@@ -121,11 +121,10 @@ def getLogger(module: str = '') -> logging.Logger:
             mod += f'.{module}'
 
     logger = logging.getLogger(mod)
-    logger.setLevel(LEVEL)
     return logger
 
 
-def enableStreamHandler(enable: bool = False) -> None:
+def enableStreamHandler(enable: bool = False, level: Union[int,str] = logging.WARNING) -> None:
     """
     enable/disable output to stderr. Enabling is useful when not
     using the UI logging window.
@@ -147,4 +146,13 @@ def enableStreamHandler(enable: bool = False) -> None:
             datefmt='%Y-%m-%d %H:%M:%S',
             )
         streamHandler.setFormatter(fmt)
+        streamHandler.setLevel(level)
         logger.addHandler(streamHandler)
+        # when we attach to a non root logger
+        # we need to explicitly set the logger to
+        # the same level as the handlers level
+        # otherwise getEffectiveLevel will look at the
+        # root_loggers level which will mostlikely be
+        # set to WARNING since basic_config has already
+        # been set.
+        logger.setLevel(level)

plottr/node/data_selector.py

@@ -115,7 +115,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
 
         for elt in self.selectedData:
             if elt not in data:
-                self.logger().warning(
+                self.node_logger.warning(
                     f'Did not find selected data {elt} in data. '
                     f'Clearing the selection.'
                 )
@@ -125,7 +125,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
             allowed_axes = data.axes(self.selectedData[0])
             for d in self.selectedData:
                 if data.axes(d) != allowed_axes:
-                    self.logger().error(
+                    self.node_logger.error(
                         f'Datasets {self.selectedData[0]} '
                         f'(with axes {allowed_axes}) '
                         f'and {d}(with axes {data.axes(d)}) are not compatible '

plottr/node/dim_reducer.py

@@ -533,7 +533,7 @@ def _applyDimReductions(self, data: DataDictBase) -> Optional[DataDictBase]:
             dnames = data.dependents()
 
         if not isinstance(data, MeshgridDataDict):
-            self.logger().debug(f"Data is not on a grid. "
+            self.node_logger.debug(f"Data is not on a grid. "
                                 f"Reduction functions are ignored, "
                                 f"axes will simply be removed.")
 
@@ -548,7 +548,7 @@ def _applyDimReductions(self, data: DataDictBase) -> Optional[DataDictBase]:
                 try:
                     idx = data[n]['axes'].index(ax)
                 except IndexError:
-                    self.logger().info(f'{ax} specified for reduction, '
+                    self.node_logger.info(f'{ax} specified for reduction, '
                                        f'but not present in data; ignore.')
 
                 kw['axis'] = idx
@@ -572,7 +572,7 @@ def _applyDimReductions(self, data: DataDictBase) -> Optional[DataDictBase]:
                         raise RuntimeError("Reduction function is None")
                     newvals = funCall(data[n]['values'], *arg, **kw)
                     if newvals.shape != targetShape:
-                        self.logger().error(
+                        self.node_logger.error(
                             f'Reduction on axis {ax} did not result in the '
                             f'right data shape. ' +
                             f'Expected {targetShape} but got {newvals.shape}.'
@@ -610,13 +610,13 @@ def validateOptions(self, data: DataDictBase) -> bool:
         for ax, reduction in self._reductions.items():
 
             if ax not in data.axes():
-                self.logger().warning(f"{ax} is not a known dimension. Removing.")
+                self.node_logger.warning(f"{ax} is not a known dimension. Removing.")
                 delete.append(ax)
                 continue
 
             if reduction is None:
                 if isinstance(data, MeshgridDataDict):
-                    self.logger().warning(f'Reduction for axis {ax} is None. '
+                    self.node_logger.warning(f'Reduction for axis {ax} is None. '
                                           f'Removing.')
                     delete.append(ax)
                 else:
@@ -635,13 +635,13 @@ def validateOptions(self, data: DataDictBase) -> bool:
                     arg = reduction[1]
                     kw = reduction[2]
             except:
-                self.logger().warning(
+                self.node_logger.warning(
                     f'Reduction for axis {ax} not in the right format.'
                 )
                 return False
 
             if not callable(fun) and not isinstance(fun, ReductionMethod):
-                self.logger().error(
+                self.node_logger.error(
                     f'Invalid reduction method for axis {ax}. '
                     f'Needs to be callable or a ReductionMethod type.'
                 )
@@ -650,7 +650,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
             # reduction methods are only defined for grid data.
             # remove reduction methods if we're not on a grid.
             if isinstance(fun, ReductionMethod) and not isinstance(data, MeshgridDataDict):
-                self.logger().info(f'Reduction set for axis {ax} is only suited for '
+                self.node_logger.info(f'Reduction set for axis {ax} is only suited for '
                                    f'grid data. Removing.')
                 delete.append(ax)
                 continue
@@ -825,22 +825,22 @@ def validateOptions(self, data: DataDictBase) -> bool:
 
         if len(availableAxes) > 0:
             if self._xyAxes[0] is None:
-                self.logger().debug(
+                self.node_logger.debug(
                     f'x-Axis is None. this will result in empty output data.')
                 return False
             elif self._xyAxes[0] not in availableAxes:
-                self.logger().warning(
+                self.node_logger.warning(
                     f'x-Axis {self._xyAxes[0]} not present in data')
                 return False
 
             if self._xyAxes[1] is None:
-                self.logger().debug(f'y-Axis is None; result will be 1D')
+                self.node_logger.debug(f'y-Axis is None; result will be 1D')
             elif self._xyAxes[1] not in availableAxes:
-                self.logger().warning(
+                self.node_logger.warning(
                     f'y-Axis {self._xyAxes[1]} not present in data')
                 return False
             elif self._xyAxes[1] == self._xyAxes[0]:
-                self.logger().warning(f"y-Axis cannot be equal to x-Axis.")
+                self.node_logger.warning(f"y-Axis cannot be equal to x-Axis.")
                 return False
 
         # below we actually mess with the reduction options, but
@@ -852,7 +852,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
         delete = []
         for n, _ in self._reductions.items():
             if n in self._xyAxes:
-                self.logger().debug(
+                self.node_logger.debug(
                     f"{n} has been selected as axis, cannot be reduced.")
                 delete.append(n)
         for n in delete:
@@ -863,7 +863,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
         for ax in availableAxes:
             if ax not in self._xyAxes:
                 if ax not in self._reductions:
-                    self.logger().debug(
+                    self.node_logger.debug(
                         f"{ax} must be reduced. "
                         f"Default to selecting first element.")
 

plottr/node/grid.py

@@ -495,7 +495,7 @@ def process(
                     )
             except GriddingError:
                 dout = data.expand()
-                self.logger().info("data could not be gridded. Falling back "
+                self.node_logger.info("data could not be gridded. Falling back "
                                    "to no grid")
                 if self.ui is not None:
                     self.ui.setGrid((GridOption.noGrid, {}))
@@ -505,16 +505,16 @@ def process(
             elif method is GridOption.guessShape:
                 dout = data
             elif method is GridOption.specifyShape:
-                self.logger().warning(
+                self.node_logger.warning(
                     f"Data is already on grid. Ignore shape.")
                 dout = data
             elif method is GridOption.metadataShape:
-                self.logger().warning(
+                self.node_logger.warning(
                     f"Data is already on grid. Ignore shape.")
                 dout = data
 
         else:
-            self.logger().error(
+            self.node_logger.error(
                 f"Unknown data type {type(data)}.")
             return None
 

plottr/node/histogram.py

@@ -125,7 +125,7 @@ def validateOptions(self, data: DataDictBase) -> bool:
         if self.histogramAxis is None:
             return True
         elif self.histogramAxis not in data.axes():
-            self.logger().error(f"'{self.histogramAxis}' is not a valid axis.")
+            self.node_logger.error(f"'{self.histogramAxis}' is not a valid axis.")
             return False
         return True
 

plottr/node/node.py

@@ -5,6 +5,7 @@
 """
 import traceback
 from logging import Logger
+import warnings
 
 from functools import wraps
 from typing import Any, Union, Tuple, Dict, Optional, Type, List, Callable, TypeVar, Generic
@@ -182,6 +183,8 @@ def __init__(self, name: str):
         else:
             self.ui = None
 
+        self.node_logger = self._logger()
+
     def setupUi(self) -> None:
         """ setting up the UI widget.
 
@@ -230,18 +233,21 @@ def update(self, signal: bool = True) -> None:
             err = f'EXCEPTION RAISED: {e[0]}: {e[1]}\n'
             for t in traceback.format_tb(e[2]):
                 err += f' -> {t}\n'
-            self.logger().error(err)
+            self.node_logger.error(err)
 
-    def logger(self) -> Logger:
+    def _logger(self) -> Logger:
         """Get a logger for this node
 
         :return: logger with a name that can be traced back easily to this node.
         """
         name = f"{self.__module__}.{self.__class__.__name__}.{self.name()}"
         logger = log.getLogger(name)
-        logger.setLevel(log.LEVEL)
         return logger
 
+    def logger(self) -> Logger:
+        warnings.warn("Calling logger on a node is deprecated. Use `node.node_logger` instead.")
+        return self._logger()
+
     def validateOptions(self, data: DataDictBase) -> bool:
         """Validate the user options
 
@@ -327,7 +333,7 @@ def process(self, dataIn: Optional[DataDictBase]=None) -> Optional[Dict[str, Opt
             self.dataShapesChanged.emit(dshapes)
 
         if not self.validateOptions(dataIn):
-            self.logger().debug("Option validation not passed")
+            self.node_logger.debug("Option validation not passed")
             return None
 
         return dict(dataOut=dataIn)

plottr/plot/mpl/__init__.py

@@ -49,7 +49,6 @@
 
 
 logger = logging.getLogger(__name__)
-logger.setLevel(logging.INFO)
 
 # matplotlib tools and settings
 symmetric_cmap = cm.get_cmap('bwr')

plottr/plot/pyqtgraph/autoplot.py

@@ -26,7 +26,7 @@
     PlotWidgetContainer, PlotWidget
 
 logger = logging.getLogger(__name__)
-logger.setLevel(logging.INFO)
+
 TIMESTRFORMAT = "%Y-%m-%dT%H%M%S"