From 15ac29c8d53df8ad4ca59e2b1734e43117a0b30f Mon Sep 17 00:00:00 2001 From: Thomas Howe Date: Sun, 16 Aug 2026 14:15:59 -0400 Subject: [PATCH] Demote per-vCon hot-path INFO logs to DEBUG (CON-763) At BDS volume the per-link and per-vCon progress lines emit ~5,000 log lines/s (38 GiB/day into SigNoz ClickHouse), 3M INFO lines per 10 minutes against ~1 warning. Keep one INFO summary per vCon (Completed processing vCon ... in N seconds) and all anomaly lines (halt, DLQ, skip); demote the rest of the routine progress lines to DEBUG. Co-Authored-By: Claude Fable 5 --- conserver/main.py | 21 +++++++++++---------- 1 file changed, 11 insertions(+), 10 deletions(-) diff --git a/conserver/main.py b/conserver/main.py index c2cc145..5eafdd3 100644 --- a/conserver/main.py +++ b/conserver/main.py @@ -245,7 +245,7 @@ def process(self) -> None: self._span = self._span_context_manager.__enter__() vcon_started = time.time() - logger.info( + logger.debug( "Started processing vCon %s with chain %s", self.vcon_id, self.chain_details["name"] @@ -351,7 +351,7 @@ def _wrap_up(self) -> None: """ egress_lists = self.chain_details.get("egress_lists", []) if egress_lists: - logger.info( + logger.debug( "Forwarding vCon %s to egress lists: %s", self.vcon_id, ", ".join(egress_lists) @@ -367,7 +367,7 @@ def _wrap_up(self) -> None: storage_backends = self.chain_details.get("storages", []) if storage_backends: - logger.info( + logger.debug( "Saving vCon %s to storage backends: %s", self.vcon_id, ", ".join(storage_backends) @@ -381,7 +381,7 @@ def _wrap_up(self) -> None: for storage_name in storage_backends: self._process_storage(storage_name) - logger.info( + logger.debug( "Completed chain %s processing for vCon: %s", self.chain_details["name"], self.vcon_id, @@ -467,7 +467,7 @@ def _process_storage_parallel(self, storage_backends: List[str]) -> None: ) storage_time = round(time.time() - storage_started, 3) - logger.info( + logger.debug( "Completed parallel storage writes for vCon %s in %s seconds (%d backends)", self.vcon_id, storage_time, @@ -485,7 +485,7 @@ def _process_tracers(self, in_vcon_uuid, out_vcon_uuid, links: list[str], link_i tracer_options = tracer.get("options") try: tracer_started = time.time() - logger.info("Processing tracer %s for vCon: %s", tracer_name, self.vcon_id) + logger.debug("Processing tracer %s for vCon: %s", tracer_name, self.vcon_id) tracer_module_name = tracer["module"] if tracer_module_name not in imported_modules: logger.debug("Importing module %s for tracer %s", tracer_module_name, tracer_name) @@ -494,7 +494,7 @@ def _process_tracers(self, in_vcon_uuid, out_vcon_uuid, links: list[str], link_i tracer_module = imported_modules[tracer_module_name] tracer_module.run(in_vcon_uuid, out_vcon_uuid, tracer_name, links, link_index, tracer_options) tracer_processing_time = round(time.time() - tracer_started, 3) - logger.info( + logger.debug( "Completed tracer %s (module: %s) for vCon: %s in %s seconds", tracer_name, tracer_module_name, @@ -529,7 +529,8 @@ def _process_link(self, links: list[str], link_index: int) -> bool: bool: Whether the chain should continue processing """ link_name = links[link_index] - logger.info("Processing link %s for vCon: %s", link_name, self.vcon_id) + # CON-763: per-link, per-vCon — ~5k lines/s at BDS volume, 38 GiB/day of log storage + logger.debug("Processing link %s for vCon: %s", link_name, self.vcon_id) link = config["links"][link_name] # Create a span for this link - automatically inherits parent span context tracer = trace.get_tracer(__name__) @@ -598,7 +599,7 @@ def _process_link(self, links: list[str], link_index: int) -> bool: "outcome": "success" if should_continue_chain else "halt", }, ) - logger.info( + logger.debug( "Completed link %s (module: %s) for vCon: %s in %s seconds", link_name, module_name, @@ -663,7 +664,7 @@ def log_llen(list_name: str) -> None: list_name: Name of the Redis list to check """ llen = queue.queue_length(list_name) - logger.info( + logger.debug( "Queue status: %s has %s pending items", list_name, llen,