Improve debug logging

- more consistent prefixes in waits
- log dynamic config when it's written
- log when waits complete, not just when they start

Author: minrk

jupyterhub_traefik_proxy/fileprovider.py

@@ -92,6 +92,7 @@ def _persist_dynamic_config(self):
                     http.pop(key)
             if not http:
                 dynamic_config.pop("http")
+        self.log.debug("Writing dynamic config %s", dynamic_config)
         self.dynamic_config_handler.atomic_dump(dynamic_config)
 
     async def _setup_traefik_dynamic_config(self):

jupyterhub_traefik_proxy/proxy.py

@@ -139,7 +139,7 @@ def __init__(self, **kwargs):
     dynamic_config = Dict()
 
     traefik_providers_throttle_duration = Unicode(
-        "0s",
+        "0.1s",
         config=True,
         help="""
             throttle traefik reloads of configuration.
@@ -300,7 +300,9 @@ async def _check_for_traefik_service(self, routespec, kind):
             json.loads(resp.body)
         except HTTPClientError as e:
             if e.code == 404:
-                self.log.debug(f"traefik {expected} not yet in {kind}")
+                self.log.debug(
+                    "Traefik route for %s: %s not yet in %s", routespec, expected, kind
+                )
                 return False
             self.log.exception(f"Error checking traefik api for {kind} {routespec}")
             return False
@@ -312,7 +314,7 @@ async def _check_for_traefik_service(self, routespec, kind):
         return True
 
     async def _wait_for_route(self, routespec):
-        self.log.debug("Waiting for %s to register with traefik", routespec)
+        self.log.debug("Traefik route for %s: waiting to register", routespec)
 
         async def _check_traefik_dynamic_conf_ready():
             """Check if traefik loaded its dynamic configuration yet"""
@@ -325,10 +327,11 @@ async def _check_traefik_dynamic_conf_ready():
 
         await exponential_backoff(
             _check_traefik_dynamic_conf_ready,
-            f"Traefik route for {routespec} configuration not available",
+            f"Traefik route for {routespec}: not ready",
             scale_factor=1.2,
             timeout=self.check_route_timeout,
         )
+        self.log.debug("Treafik route for %s: registered", routespec)
 
     async def _traefik_api_request(self, path):
         """Make an API request to traefik"""
@@ -494,7 +497,6 @@ async def _setup_traefik_dynamic_config(self):
                 "middlewares": {},
             }
         }
-        dynamic_config["http"]
         routers = dynamic_config["http"]["routers"]
         middlewares = dynamic_config["http"]["middlewares"]
         routers["route_api"] = {