QFw: let the logs tier carry the client's story lines

backends/qfw_telemetry/__init__.py

@@ -69,6 +69,9 @@
 	"all": logging.DEBUG,
 }
 LOGS_ALL = "all"
+# QFw's own loggers. The tier opens this namespace to its level so a
+# process whose root logger is quieter still sends QFw's lines.
+LOG_NAMESPACE = "qfw"
 
 # Loggers whose records never leave through the logs tier: the SDK and the
 # HTTP stack it exports with. A failed export logs a warning; exporting that
@@ -146,6 +149,7 @@ def __init__(self):
 		self.logger_provider = None
 		self.log_handler = None
 		self.logs_level = None
+		self.log_namespace_level = None
 
 
 _STATE = _State()
@@ -408,6 +412,8 @@ def _install_log_handler(logger_provider, level, keep_internals=False):
 
 	The root logger's own level still applies first: a record below it never
 	reaches any handler, this one included. The handler only narrows further.
+	The one exception is QFw's own namespace, which the tier opens to its
+	level, see _open_log_namespace.
 	"""
 	# The SDK marks this handler deprecated in favour of the one in
 	# opentelemetry-instrumentation-logging, a package QFw does not carry.
@@ -422,6 +428,7 @@ def _install_log_handler(logger_provider, level, keep_internals=False):
 		handler = LoggingHandler(level=level, logger_provider=logger_provider)
 	handler.addFilter(_LogSourceFilter(keep_internals))
 	logging.getLogger().addHandler(handler)
+	_open_log_namespace(level)
 	return handler
 
 
@@ -433,6 +440,37 @@ def _remove_log_handler():
 		except Exception:
 			pass
 	_STATE.log_handler = None
+	_close_log_namespace()
+
+
+def _open_log_namespace(level):
+	"""
+	Let QFw's own loggers, the "qfw" namespace, pass records at the tier's
+	level when the root logger would not.
+
+	A record is dropped at its logger when it is below that logger's
+	effective level, before any handler sees it, and a logger with no level
+	of its own takes the root's. A DEFw service opens its root logger, but a
+	Qiskit client out of the box has it at Python's default, WARNING, and
+	the story lines are debug: without this the client's half of a job's
+	story never left the process. Only the namespace is opened; everything
+	else in the process still answers to the root logger's level. The level
+	the namespace had is kept, and given back when the tier goes.
+	"""
+	if level is None:
+		return
+	logger = logging.getLogger(LOG_NAMESPACE)
+	if logger.getEffectiveLevel() <= level:
+		return
+	if _STATE.log_namespace_level is None:
+		_STATE.log_namespace_level = logger.level
+	logger.setLevel(level)
+
+
+def _close_log_namespace():
+	if _STATE.log_namespace_level is not None:
+		logging.getLogger(LOG_NAMESPACE).setLevel(_STATE.log_namespace_level)
+		_STATE.log_namespace_level = None
 
 
 def _metric_export_interval_ms():
@@ -631,15 +669,19 @@ def logs_enabled():
 	DEFw's set_logging_level_helper removes every handler from the root
 	logger whenever a process sets or changes its DEFw log level, which a
 	service does after QFw has configured telemetry. So this does not only
-	answer; it puts the tier's handler back if it has gone, and QFw's own
-	call sites ask before they write a line.
+	answer; it puts the tier's handler back if it has gone, keeps QFw's own
+	loggers open to the tier, and QFw's own call sites ask before they write
+	a line.
 	"""
 	handler = _STATE.log_handler
 	if handler is None:
 		return False
 	root = logging.getLogger()
 	if handler not in root.handlers:
 		root.addHandler(handler)
+	# The same DEFw call can raise the root logger above the tier, which
+	# closes the namespace again when it has no level of its own.
+	_open_log_namespace(_STATE.logs_level)
 	return True
 
 

docs/design/benchmarking.md

@@ -228,7 +228,10 @@ and SDKs for all benchmarking/profiling telemetry, using all three signals:
   transport internals only with `all`, and `error` carries real errors only.
   The instrumentation layer writes the story's five milestone lines itself
   (submitted, received, executing, done, job done), while the job's span is
-  current, so every backend has lines under its waterfall.
+  current, so every backend has lines under its waterfall. The tier opens
+  QFw's own `qfw.*` loggers to its level, so a Qiskit client whose root
+  logger sits at Python's default `WARNING` still sends its lines;
+  everything else in a process answers to the root logger's level.
 
 Adopting the standard has consequences the bespoke format could not offer:
 

tests/mock/test_instrumentation.py

@@ -102,11 +102,10 @@ def recording():
 		logger_provider=logger_provider, logs_level=logging.DEBUG)
 	assert instrumentation.enabled()
 	assert qfw_telemetry.logs_enabled()
-	# The story lines are debug; the root logger must let them through.
-	root_level = logging.getLogger().level
-	logging.getLogger().setLevel(logging.DEBUG)
+	# The story lines are debug and the root logger may be quieter than
+	# that: the tier opens QFw's own loggers itself, as it must for a
+	# real client, so the fixture leaves the root alone.
 	yield _Recording(exporter, reader, log_exporter)
-	logging.getLogger().setLevel(root_level)
 	qfw_telemetry.shutdown()
 	assert not instrumentation.enabled()
 

tests/test_qfw_telemetry.py

@@ -346,6 +346,85 @@ def test_logs_tier_reattaches_after_defw_strips_the_root_handlers():
     assert handler not in root.handlers
 
 
+def test_logs_tier_carries_qfw_lines_past_a_quiet_root_logger():
+    import logging
+    pytest.importorskip("opentelemetry.sdk")
+    from opentelemetry.sdk._logs import LoggerProvider
+    from opentelemetry.sdk._logs.export import SimpleLogRecordProcessor
+    from opentelemetry.sdk.trace import TracerProvider
+    try:
+        from opentelemetry.sdk._logs.export import InMemoryLogRecordExporter
+    except ImportError:  # older SDKs
+        from opentelemetry.sdk._logs.export import (
+            InMemoryLogExporter as InMemoryLogRecordExporter)
+
+    exporter = InMemoryLogRecordExporter()
+    logger_provider = LoggerProvider()
+    logger_provider.add_log_record_processor(SimpleLogRecordProcessor(exporter))
+    root = logging.getLogger()
+    namespace = logging.getLogger("qfw")
+    client = logging.getLogger("qfw.client")
+    root_level, namespace_level = root.level, namespace.level
+    # A Qiskit client out of the box: nothing has configured logging, the
+    # root logger sits at Python's default and the story lines are debug.
+    root.setLevel(logging.WARNING)
+    namespace.setLevel(logging.NOTSET)
+    assert not client.isEnabledFor(logging.DEBUG)
+    try:
+        telemetry.use_providers(
+            TracerProvider(), logger_provider=logger_provider,
+            logs_level=logging.DEBUG)
+        assert client.isEnabledFor(logging.DEBUG)
+        assert root.level == logging.WARNING
+        with telemetry.tracer().start_as_current_span("qfw.app.job") as job:
+            client.debug("submitted job %s: 1 circuit(s), 1024 shots", "j-1")
+            # The root's level still governs everyone else.
+            logging.getLogger("qiskit.transpiler").debug("stays local")
+            logging.debug("so does the root logger's own debug line")
+        # DEFw raising the root logger later must not close QFw's loggers.
+        root.setLevel(logging.CRITICAL)
+        namespace.setLevel(logging.NOTSET)
+        assert telemetry.logs_enabled() is True
+        assert client.isEnabledFor(logging.DEBUG)
+        telemetry.shutdown()
+        # The tier gives the namespace back as it found it.
+        assert namespace.level == logging.NOTSET
+        assert not client.isEnabledFor(logging.DEBUG)
+    finally:
+        telemetry.shutdown()
+        root.setLevel(root_level)
+        namespace.setLevel(namespace_level)
+    finished = getattr(exporter, "get_finished_log_records",
+                       getattr(exporter, "get_finished_logs", None))()
+    assert [(r.log_record.body, r.log_record.trace_id) for r in finished] == [
+        ("submitted job j-1: 1 circuit(s), 1024 shots",
+         job.get_span_context().trace_id)]
+
+
+def test_logs_tier_leaves_an_open_root_logger_alone():
+    import logging
+    pytest.importorskip("opentelemetry.sdk")
+    from opentelemetry.sdk._logs import LoggerProvider
+    from opentelemetry.sdk.trace import TracerProvider
+
+    root = logging.getLogger()
+    namespace = logging.getLogger("qfw")
+    root_level, namespace_level = root.level, namespace.level
+    root.setLevel(logging.DEBUG)
+    namespace.setLevel(logging.NOTSET)
+    try:
+        telemetry.use_providers(
+            TracerProvider(), logger_provider=LoggerProvider(),
+            logs_level=logging.DEBUG)
+        # Already open through the root: the namespace gets no level of its
+        # own, so a process that manages its logging sees no change.
+        assert namespace.level == logging.NOTSET
+    finally:
+        telemetry.shutdown()
+        root.setLevel(root_level)
+        namespace.setLevel(namespace_level)
+
+
 def _attr_value(value):
     """Unwrap one OTLP AnyValue into a plain Python value."""
     for key in ("stringValue", "boolValue", "arrayValue"):