Improve logging of bare exceptions and other cleanups. (#922)

Author: thetorpedodog

jupyter_server/base/handlers.py

@@ -99,7 +99,7 @@ def set_default_headers(self):
                 # tornado raise Exception (not a subclass)
                 # if method is unsupported (websocket and Access-Control-Allow-Origin
                 # for example, so just ignore)
-                self.log.debug(e)
+                self.log.exception("Could not set default headers: %s", e)
 
     @property
     def cookie_name(self):
@@ -723,7 +723,7 @@ def write_error(self, status_code, **kwargs):
                 reply["message"] = "Unhandled error"
                 reply["reason"] = None
                 reply["traceback"] = "".join(traceback.format_exception(*exc_info))
-        self.log.warning(reply["message"])
+        self.log.warning("wrote error: %r", reply["message"])
         self.finish(json.dumps(reply))
 
     def get_login_url(self):

jupyter_server/extension/manager.py

@@ -1,6 +1,4 @@
 import importlib
-import sys
-import traceback
 
 from tornado.gen import multi
 from traitlets import Any, Bool, Dict, HasTraits, Instance, Unicode, default, observe
@@ -326,7 +324,13 @@ def add_extension(self, extension_name, enabled=False):
         except Exception as e:
             if self.serverapp.reraise_server_extension_failures:
                 raise
-            self.log.warning(e)
+            self.log.warning(
+                "%s | error adding extension (enabled: %s): %s",
+                extension_name,
+                enabled,
+                e,
+                exc_info=True,
+            )
         return False
 
     def link_extension(self, name):
@@ -337,11 +341,11 @@ def link_extension(self, name):
                 # Link extension and store links
                 extension.link_all_points(self.serverapp)
                 self.linked_extensions[name] = True
-                self.log.info(f"{name} | extension was successfully linked.")
+                self.log.info("%s | extension was successfully linked.", name)
             except Exception as e:
                 if self.serverapp.reraise_server_extension_failures:
                     raise
-                self.log.warning(e)
+                self.log.warning("%s | error linking extension: %s", name, e, exc_info=True)
 
     def load_extension(self, name):
         extension = self.extensions.get(name)
@@ -352,21 +356,17 @@ def load_extension(self, name):
             except Exception as e:
                 if self.serverapp.reraise_server_extension_failures:
                     raise
-                self.log.debug("".join(traceback.format_exception(*sys.exc_info())))
-                self.log.warning(
-                    "{name} | extension failed loading with message: {error}".format(
-                        name=name, error=str(e)
-                    )
-                )
+                self.log.warning("%s | extension failed loading with message: %s", name, e)
+                self.log.exception("%s | stack trace", name)
             else:
-                self.log.info(f"{name} | extension was successfully loaded.")
+                self.log.info("%s | extension was successfully loaded.", name)
 
     async def stop_extension(self, name, apps):
         """Call the shutdown hooks in the specified apps."""
         for app in apps:
-            self.log.debug(f'{name} | extension app "{app.name}" stopping')
+            self.log.debug("%s | extension app %r stopping", name, app.name)
             await app.stop_extension()
-            self.log.debug(f'{name} | extension app "{app.name}" stopped')
+            self.log.debug("%s | extension app %r stopped", name, app.name)
 
     def link_all_extensions(self):
         """Link all enabled extensions

jupyter_server/services/kernels/kernelmanager.py

@@ -227,15 +227,15 @@ async def start_kernel(self, kernel_id=None, path=None, **kwargs):
             kernel.execution_state = "starting"
             kernel.reason = ""
             kernel.last_activity = utcnow()
-            self.log.info("Kernel started: %s" % kernel_id)
-            self.log.debug("Kernel args: %r" % kwargs)
+            self.log.info("Kernel started: %s", kernel_id)
+            self.log.debug("Kernel args: %r", kwargs)
 
             # Increase the metric of number of kernels running
             # for the relevant kernel type by 1
             KERNEL_CURRENTLY_RUNNING_TOTAL.labels(type=self._kernels[kernel_id].kernel_name).inc()
 
         else:
-            self.log.info("Using existing kernel: %s" % kernel_id)
+            self.log.info("Using existing kernel: %s", kernel_id)
 
         # Initialize culling if not already
         if not self._initialized_culler:
@@ -248,8 +248,8 @@ async def _finish_kernel_start(self, kernel_id):
         if hasattr(km, "ready"):
             try:
                 await km.ready
-            except Exception as e:
-                self.log.exception(e)
+            except Exception:
+                self.log.exception("Error waiting for kernel manager ready")
                 return
 
         self._kernel_ports[kernel_id] = km.ports
@@ -276,7 +276,7 @@ def ports_changed(self, kernel_id):
         changed_ports = self._get_changed_ports(kernel_id)
         if changed_ports:
             # If changed, update captured ports and return True, else return False.
-            self.log.debug(f"Port change detected for kernel: {kernel_id}")
+            self.log.debug("Port change detected for kernel: %s", kernel_id)
             self._kernel_ports[kernel_id] = changed_ports
             return True
         return False

tests/extension/test_app.py

@@ -163,10 +163,10 @@ async def _stop(*args):
     run_sync(jp_serverapp.cleanup_extensions())
     assert {msg for *_, msg in caplog.record_tuples} == {
         "Shutting down 2 extensions",
-        'jupyter_server_terminals | extension app "jupyter_server_terminals" stopping',
-        f'{extension_name} | extension app "mockextension" stopping',
-        'jupyter_server_terminals | extension app "jupyter_server_terminals" stopped',
-        f'{extension_name} | extension app "mockextension" stopped',
+        "jupyter_server_terminals | extension app 'jupyter_server_terminals' stopping",
+        f"{extension_name} | extension app 'mockextension' stopping",
+        "jupyter_server_terminals | extension app 'jupyter_server_terminals' stopped",
+        f"{extension_name} | extension app 'mockextension' stopped",
     }
 
     # check the shutdown method was called twice