Merged PR posit-dev/positron-python#115: fix ipkernel logging

Merge pull request #115 from posit-dev/fix-logging

fix ipkernel logging
--------------------
Commit message for posit-dev/positron-python@3922350:

fix ipkernel logging

The root logger wasn't configured to use IPKernelApp's handlers, and the
`logfile` argument was being passed to `initialize` which overwrote the
log file we wanted with a log of the the executed code inputs.

Also switched to per-module named loggers instead of root -- just lets
us easily see where a log originated from.


Authored-by: Wasim Lorgat <[email protected]>
Signed-off-by: Wasim Lorgat <[email protected]>

Author: seeM

extensions/positron-python/pythonFiles/positron/environment.py

@@ -11,6 +11,8 @@
 from .inspectors import get_inspector, MAX_ITEMS
 from .utils import get_qualname
 
+logger = logging.getLogger(__name__)
+
 
 @enum.unique
 class EnvironmentMessageType(str, enum.Enum):
@@ -271,7 +273,7 @@ def _send_message(self, msg: EnvironmentMessage) -> None:
         Send a message through the environment comm to the client.
         """
         if self.env_comm is None:
-            logging.warning("Cannot send message, environment comm is not open")
+            logger.warning("Cannot send message, environment comm is not open")
             return
 
         self.env_comm.send(msg)
@@ -517,7 +519,7 @@ def _summarize_variable(self, key: Any, value: Any) -> Optional[EnvironmentVaria
             )
 
         except Exception as err:
-            logging.warning(err, exc_info=True)
+            logger.warning(err, exc_info=True)
             return EnvironmentVariable(
                 display_name=str(key),
                 display_value=get_qualname(value),

extensions/positron-python/pythonFiles/positron/inspectors.py

@@ -23,6 +23,8 @@
 # conditional property lookup
 __POSITRON_DEFAULT__ = object()
 
+logger = logging.getLogger(__name__)
+
 #
 # Base inspector
 #
@@ -156,7 +158,7 @@ def has_child(self, value: Any, child_name: str) -> bool:
                 index = int(child_name)
                 return index < self.get_length(value)
             except Exception:
-                logging.warning(f"Unable to find child value at '{child_name}'", exc_info=True)
+                logger.warning(f"Unable to find child value at '{child_name}'", exc_info=True)
 
         return False
 
@@ -168,7 +170,7 @@ def get_child(self, value: Any, child_name: str) -> Any:
                 index = int(child_name)
                 child_value = value[index]
             except Exception:
-                logging.warning(f"Unable to find child value at '{child_name}'", exc_info=True)
+                logger.warning(f"Unable to find child value at '{child_name}'", exc_info=True)
 
         return child_value
 
@@ -371,7 +373,7 @@ def get_column(self, value: Any, column_name: str) -> Any:
             values = column.values.tolist()
         except Exception:
             values = []
-            logging.warning("Unable to get Pandas column: %s", column_name, exc_info=True)
+            logger.warning("Unable to get Pandas column: %s", column_name, exc_info=True)
 
         return values
 
@@ -395,7 +397,7 @@ def get_column_display_type(self, value: Any, column_name: str) -> str:
             display_type = f"{column_type} [{size}]"
         except Exception:
             display_type = ""
-            logging.warning("Unable to get Pandas column type: %s", column_name, exc_info=True)
+            logger.warning("Unable to get Pandas column type: %s", column_name, exc_info=True)
 
         return display_type
 
@@ -432,7 +434,7 @@ def get_display_value(
             display_value = value.to_string(index=False, max_rows=MAX_ITEMS)
             return (display_value, True)
         except Exception:
-            logging.warning("Unable to display Pandas Series", exc_info=True)
+            logger.warning("Unable to display Pandas Series", exc_info=True)
             display_value = self.get_display_type(value)
             return (display_value, True)
 
@@ -451,7 +453,7 @@ def has_child(self, value: Any, child_name: str) -> bool:
             index = int(child_name)
             return index < self.get_length(value)
         except Exception:
-            logging.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
+            logger.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
 
         return False
 
@@ -462,7 +464,7 @@ def get_child(self, value: Any, child_name: str) -> Any:
             index = int(child_name)
             child_value = value.iat[index]
         except Exception:
-            logging.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
+            logger.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
 
         return child_value
 
@@ -481,7 +483,7 @@ def summarize_children(
                 if summary is not None:
                     children.append(summary)
         except Exception:
-            logging.warning("Error summarizing Pandas Series children", exc_info=True)
+            logger.warning("Error summarizing Pandas Series children", exc_info=True)
 
         return children
 
@@ -536,7 +538,7 @@ def get_column(self, value: Any, child_name: str) -> Any:
             column = value.get_column(child_name)
             return column.to_list()
         except Exception:
-            logging.warning("Unable to get Polars child: %s", child_name, exc_info=True)
+            logger.warning("Unable to get Polars child: %s", child_name, exc_info=True)
             return []
 
     def get_column_display_type(self, value: Any, column_name: str) -> str:
@@ -558,7 +560,7 @@ def get_column_display_type(self, value: Any, column_name: str) -> str:
 
             display_type = f"{column_type} [{size}]"
         except Exception:
-            logging.warning("Unable to get Polars column type: %s", column_name, exc_info=True)
+            logger.warning("Unable to get Polars column type: %s", column_name, exc_info=True)
             display_type = ""
 
         return display_type
@@ -602,7 +604,7 @@ def get_display_value(
                 True,
             )
         except Exception:
-            logging.warning("Unable to display Ndarray", exc_info=True)
+            logger.warning("Unable to display Ndarray", exc_info=True)
             return (self.get_display_type(value), True)
 
     def get_display_type(self, value: Any) -> str:
@@ -637,7 +639,7 @@ def has_child(self, value: Any, child_name: str) -> bool:
             index = int(child_name)
             return index < self.get_length(value)
         except Exception:
-            logging.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
+            logger.warning(f"Unable to find Pandas Series child at '{child_name}'", exc_info=True)
         return False
 
     def get_child(self, value: Any, child_name: str) -> Any:
@@ -652,7 +654,7 @@ def get_child(self, value: Any, child_name: str) -> Any:
 
             return child_value
         except Exception:
-            logging.warning("Unable to get ndarray child: %s", child_name, exc_info=True)
+            logger.warning("Unable to get ndarray child: %s", child_name, exc_info=True)
             return []
 
     def summarize_children(
@@ -670,7 +672,7 @@ def summarize_children(
                 if summary is not None:
                     children.append(summary)
         except Exception:
-            logging.warning("Error summarizing Numpy ndarray children", exc_info=True)
+            logger.warning("Error summarizing Numpy ndarray children", exc_info=True)
 
         return children
 
@@ -681,7 +683,7 @@ def equals(self, value1: Any, value2: Any) -> bool:
 
             return np.array_equal(value1, value2)
         except Exception as err:
-            logging.warning("numpy equals %s", err, exc_info=True)
+            logger.warning("numpy equals %s", err, exc_info=True)
 
         # Fallback to comparing the raw bytes
         if value1.shape != value2.shape:

extensions/positron-python/pythonFiles/positron/plots.py

@@ -11,6 +11,8 @@
 
 from IPython.core.interactiveshell import InteractiveShell
 
+logger = logging.getLogger(__name__)
+
 
 class PlotClientMessageImage(dict):
     """
@@ -107,7 +109,7 @@ def receive_message(self, msg) -> None:
 
         figure_comm = self.comms.get(comm_id, None)
         if figure_comm is None:
-            logging.warning(f"Plot figure comm {comm_id} not found")
+            logger.warning(f"Plot figure comm {comm_id} not found")
             return
 
         pickled = self.figures.get(comm_id, None)

extensions/positron-python/pythonFiles/positron/positron_ipkernel.py

@@ -99,7 +99,7 @@ def handle_pre_execute(self) -> None:
         try:
             self.snapshot_user_ns()
         except Exception:
-            logging.warning("Failed to snapshot user namespace", exc_info=True)
+            logger.warning("Failed to snapshot user namespace", exc_info=True)
 
     def handle_post_execute(self) -> None:
         """
@@ -117,7 +117,7 @@ def handle_post_execute(self) -> None:
             assigned, removed = self.compare_user_ns()
             self.env_service.send_update(assigned, removed)
         except Exception as err:
-            logging.warning(err, exc_info=True)
+            logger.warning(err, exc_info=True)
 
     def get_user_ns(self) -> dict:
         return self.shell.user_ns or {}  # type: ignore
@@ -200,7 +200,7 @@ def compare_user_ns(self) -> Tuple[dict, set]:
                         assigned[key] = v2
 
             except Exception as err:
-                logging.warning("err: %s", err, exc_info=True)
+                logger.warning("err: %s", err, exc_info=True)
 
         return assigned, removed
 
@@ -317,7 +317,7 @@ def delete_vars(self, names: Iterable, parent) -> Tuple[dict, set]:
             try:
                 self.shell.del_var(name, False)  # type: ignore
             except Exception:
-                logging.warning(f"Unable to delete variable '{name}'")
+                logger.warning(f"Unable to delete variable '{name}'")
                 pass
 
         assigned, removed = self.compare_user_ns()

extensions/positron-python/pythonFiles/positron/positron_jedilsp.py

@@ -277,7 +277,7 @@ def positron_completion(
         ]
     except ValueError:
         # Ignore LSP errors for completions from invalid line/column ranges.
-        logging.info("LSP completion error", exc_info=True)
+        logger.info("LSP completion error", exc_info=True)
         completion_items = []
 
     return CompletionList(is_incomplete=False, items=completion_items) if completion_items else None
@@ -329,7 +329,7 @@ def positron_hover(
         return hover(server, params)
     except ValueError:
         # Ignore LSP errors for hover over invalid line/column ranges.
-        logging.info("LSP hover error", exc_info=True)
+        logger.info("LSP hover error", exc_info=True)
 
     return None
 
@@ -378,7 +378,7 @@ def positron_code_action(
         return code_action(server, params)
     except ValueError:
         # Ignore LSP errors for actions with invalid line/column ranges.
-        logging.info("LSP codeAction error", exc_info=True)
+        logger.info("LSP codeAction error", exc_info=True)
 
     return None
 

extensions/positron-python/pythonFiles/positron_language_server.py

@@ -21,12 +21,7 @@
 logger = logging.getLogger(__name__)
 
 
-def initialize_config() -> None:
-    """
-    Initialize the configuration for the Positron Python Language Server
-    and REPL Kernel.
-    """
-
+def parse_args() -> argparse.Namespace:
     # Given we're using TCP, support a subset of the Jedi LSP configuration
     parser = argparse.ArgumentParser(
         prog="positron-language-server",
@@ -54,27 +49,21 @@ def initialize_config() -> None:
     )
     parser.add_argument(
         "-f",
-        help="location of the IPyKernel configuration file",
+        "--connection-file",
+        help="location of the IPyKernel connection file",
         type=str,
     )
-    parser.add_argument(
-        "-v",
-        "--verbose",
-        help="increase verbosity of log output",
-        action="count",
-        default=0,
-    )
     args = parser.parse_args()
-
     args.loglevel = args.loglevel.upper()
-    if args.logfile:
-        logging.basicConfig(
-            filename=args.logfile,
-            filemode="w",
-            level=args.loglevel,
-        )
-    else:
-        logging.basicConfig(stream=sys.stderr, level=args.loglevel)
+
+    return args
+
+
+if __name__ == "__main__":
+    exit_status = 0
+
+    # Parse command-line arguments
+    args = parse_args()
 
     # Start the debugpy debugger if a port was specified
     if args.debugport is not None:
@@ -83,18 +72,43 @@ def initialize_config() -> None:
 
             debugpy.listen(args.debugport)
         except Exception as error:
-            logging.warning(f"Unable to start debugpy: {error}", exc_info=True)
-
-
-if __name__ == "__main__":
-    exit_status = 0
-
-    # Init the configuration args
-    initialize_config()
+            logger.warning(f"Unable to start debugpy: {error}", exc_info=True)
+
+    # Configure logging by passing the IPKernelApp traitlets application by passing a logging config
+    # dict. See: https://docs.python.org/3/library/logging.config.html#logging-config-dictschema for
+    # more info about this schema.
+    handlers = ["console"] if args.logfile is None else ["file"]
+    logging_config = {
+        "loggers": {
+            "root": {
+                "level": args.loglevel,
+                "handlers": handlers,
+            },
+            "IPKernelApp": {
+                "handlers": handlers,
+            },
+        }
+    }
+    if args.logfile is not None:
+        logging_config["handlers"] = {
+            "file": {
+                "class": "logging.FileHandler",
+                "formatter": "console",
+                "level": args.loglevel,
+                "filename": args.logfile,
+            }
+        }
 
     # Start Positron's IPyKernel as the interpreter for our console.
-    app = kernelapp.IPKernelApp.instance(kernel_class=PositronIPyKernel)
-    app.initialize()
+    app = kernelapp.IPKernelApp.instance(
+        kernel_class=PositronIPyKernel,
+        connection_file=args.connection_file,
+        log_level=args.loglevel,
+        logging_config=logging_config,
+    )
+    # Initialize with empty argv, otherwise BaseIPythonApplication.initialize reuses our
+    # command-line arguments in unexpected ways (e.g. logfile instructs it to log executed code).
+    app.initialize(argv=[])
     app.kernel.start()
 
     logger.info(f"Process ID {os.getpid()}")
@@ -104,7 +118,7 @@ def initialize_config() -> None:
     loop = asyncio.get_event_loop()
 
     # Enable asyncio debug mode.
-    if logging.getLogger().level == logging.DEBUG:
+    if args.loglevel == "DEBUG":
         loop.set_debug(True)
 
     try: