Add runtime debug logs across plan publication and query execution

[zzylol]

Dependency stack: main → #768 → #737 → #749 → #771 → #728 → #770 → #763 → #765 → #761 → #742 → #759

Independent follow-ups to #765: #756 (diagnostics), #766 (runtime controls and overhead inspection).

Why

A physical plan and its queries can cross controller, backend, precompute, and storage boundaries without enough shared context to identify where a failure occurred.

What

Before this PR: A failed query could leave operators searching separate logs without a consistent plan identifier, per-call context, or execution timing.

After this PR: Plan publication and activation events carry plan ID and version, per-process call ID, elapsed time, and error details on failure. Query calls carry a unique call ID and elapsed time; installed DAG nodes log their type, bounded syntax arguments, input node IDs, and inclusive duration, including the first failing node. Precompute worker errors include the captured plan generation, and storage catalog installation and validation are logged. Inner debug spans cover compilation, publication, validation, worker processing, storage installation, and installed query preparation and execution. Set RUST_LOG=info,asap_runtime_debug=debug on both processes to enable workflow debug events; use RUST_LOG=info to hide them. Both processes use only RUST_LOG and default to info when it is unset or invalid. The backend --log-level flag and redundant Compose arguments were removed. The controller and backend use the same console layout, and the runtime-info debug message no longer prints the Authorization header value.

A call ID is local to one process. Error details may contain query text, so log access should be restricted accordingly. See docs/runtime-debugging.md for filters and correlation fields.

Observed success output (local run)

With RUST_LOG=info,asap_runtime_debug=debug, a real controller process handled a valid read-only POST /api/v1/physical-plan/cost-manifests request for quantile_over_time(0.99, m[1m]): HTTP 200, one manifest. This demonstrates compilation, not plan publication or activation. Selected controller stdout:

2026-09-22T14:58:15.980733Z DEBUG select_logical_roots_with_trace{query_count=1 root_count=1}: asap_runtime_debug: control_plane/src/physical/compiler.rs:2175: logical root selection started
2026-09-22T14:58:16.012005Z DEBUG compile_for_frontend{frontend=PromQl plan_version=1 query_count=1}: asap_runtime_debug: control_plane/src/physical/compiler.rs:980: physical plan compiler entered
2026-09-22T14:58:16.018361Z DEBUG compile_for_frontend{frontend=PromQl plan_version=1 query_count=1}:build_transmission_plan{plan_id=8436318272432547847 plan_version=1 producer_count=0}: asap_runtime_debug: control_plane/src/physical/compiler.rs:399: transmission plan construction started

The real data plane process passed cargo test -p data_plane --test asapquery_compatibility_process_e2e shared_exact_dashboard_executes_selected_workload -- --nocapture (1 passed). The first instant query is sum by (service) (sum_over_time(asap_demo_gauge[5s])) (compat-query-0, call_id=1); the test asserts api=24 and worker=24. The second is sum by (service) (count_over_time(asap_demo_gauge[5s])) (compat-query-1, call_id=2); it asserts api=4 and worker=2. Its count readout is followed by a sum across instances, so the IR correctly shows exact_readout/count followed by logical/aggregate/sum. The test also checks their quotient as an instant query (api=6, worker=12) and a two-step range query. Actual data plane stdout after this PR's node-detail change (op identifies the IR node, syntax shows bounded operator arguments, and inputs links its children):

2026-09-22T15:17:26.747768Z DEBUG query_call{call_id=1}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-0 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:197: installed query node started query_id=compat-query-0 node_id=QueryNodeId(0) op="logical/aggregate/sum" syntax=operation=Sum grouping=by(service) inputs=[QueryNodeId(1)] evaluation_ms=1790090230000
2026-09-22T15:17:26.747975Z DEBUG query_call{call_id=1}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-0 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:197: installed query node started query_id=compat-query-0 node_id=QueryNodeId(1) op="exact_readout/sum" syntax=readout=Sum inputs=[QueryNodeId(2)] evaluation_ms=1790090230000
2026-09-22T15:17:26.755699Z DEBUG query_call{call_id=2}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-1 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:197: installed query node started query_id=compat-query-1 node_id=QueryNodeId(0) op="logical/aggregate/sum" syntax=operation=Sum grouping=by(service) inputs=[QueryNodeId(1)] evaluation_ms=1790090230000
2026-09-22T15:17:26.755802Z DEBUG query_call{call_id=2}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-1 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:197: installed query node started query_id=compat-query-1 node_id=QueryNodeId(1) op="exact_readout/count" syntax=readout=Count inputs=[QueryNodeId(2)] evaluation_ms=1790090230000
2026-09-22T15:17:26.763256Z DEBUG query_call{call_id=3}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-2 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:197: installed query node started query_id=compat-query-2 node_id=QueryNodeId(0) op="logical/binary" syntax=operation=Div return_bool=false inputs=[QueryNodeId(1), QueryNodeId(4)] evaluation_ms=1790090230000
2026-09-22T15:17:26.765361Z DEBUG query_call{call_id=3}:execute_logical_entry{plan_id=17031237013456621470 plan_version=1 query_id=compat-query-2 evaluation_ms=1790090230000}: asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/logical_dag.rs:275: installed query node completed query_id=compat-query-2 node_id=QueryNodeId(0) op="logical/binary" syntax=operation=Div return_bool=false elapsed_us=2107

Timestamps, IDs and durations vary between runs.

Precompute and storage log output

The focused scheduler test cargo test -p data_plane --lib shared_dependency_executes_once_and_replay_reads_committed_value -- --nocapture passed. Its test fixture exercises actual DAG node execution and committed-sink replay. Selected event fields from the captured log (the enclosing span is precompute_dag{plan_id=7 plan_version=1 sink_node_id=3 summary_definition=4 window_start_ms=10 window_end_ms=20}):

precompute DAG execution started node_count=5 edge_count=5
precompute node started node_id=3 op=SummarySubtract syntax= inputs=[1, 2]
precompute node completed node_id=3 op=SummarySubtract elapsed_us=37
precompute DAG sink commit completed success=true
precompute DAG reused committed sink

The real-process aggregation E2E test shared_exact_dashboard_executes_selected_workload passed (1 passed). These are selected event fields from its captured stdout; ancestor worker/query spans and timestamps are omitted for readability:

precompute DAG execution started node_count=4 edge_count=3
precompute node used materialized input node_id=1 op=SummaryAgg
SDS descriptor binding resolved sid=2 policy_fp=policy_fp:c32485be5a4aff65 summary_descriptor_hash=2ae3707c956e20b9 data_descriptor_hash=218fd8698d2a465e plan_id=17031237013456621470 plan_version=1
SketchStore precompute window append completed sid=2 policy_fp=policy_fp:c32485be5a4aff65 aggregation_type=Sum window_start_ms=1790091231000 window_end_ms=1790091236000 accepted=true
SDS summary publication acknowledged plan_id=17031237013456621470 plan_version=1 sid=2 summary_definition=14061510989162676069 window_start_ms=1790091231000 window_end_ms=1790091236000 revision=2
SketchStore exact range read completed sid=1 start_unix_ms=1790091235000 end_unix_ms=1790091240000 series_count=1 elapsed_us=98

IDs, timestamps, and durations vary between runs. The worker's existing ancestor span can contain group label values.

Observed failure-path output (local smoke run)

Built this PR with cargo build -p control_plane -p data_plane --bins, then started both binaries with RUST_LOG=info,asap_runtime_debug=debug on loopback ports. The controller received a deliberately invalid compile request (queries: [], HTTP 422); the data plane used an empty streaming bootstrap and received GET /api/v1/query?query=up without an installed query plan. These requests exercise the failure paths; they do not show a deployed plan succeeding.

Controller stdout:

2026-09-22T14:50:14.874762Z  INFO control_plane: control_plane/src/main.rs:181: control plane API listening on 127.0.0.1:36555
2026-09-22T14:50:14.965028Z DEBUG asap_runtime_debug: control_plane/src/main.rs:283: physical plan compilation requested call_id=1 frontend=PromQl
2026-09-22T14:50:14.965139Z  WARN control_plane: control_plane/src/main.rs:313: physical plan compilation failed call_id=1 status=422 Unprocessable Entity error="queries must be non-empty; distributed deployment requires collectors and backend-local deployment requires none"

Data plane stdout (also written to query_engine.log):

2026-09-22T14:50:15.498721Z  INFO data_plane: data_plane/src/main.rs:527: Starting Query Engine Rust
2026-09-22T14:50:15.584750Z DEBUG asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/engine.rs:1111: query call started call_id=1 operation="promql_instant" evaluation_ms=1790088615577
2026-09-22T14:50:15.588177Z DEBUG asap_runtime_debug: data_plane/src/query_engines/asap_query_engine/engine.rs:29: query call could not be served by ASAP tier call_id=1 operation="promql_instant" elapsed_ms=3 error=no compatible aggregation in asap_query: installed QueryPlan resolver could not serve `up`: 

The asap_runtime_debug lines appear at DEBUG in both processes under the same filter; the ordinary startup and failure messages retain their normal levels. Timestamps, ports and elapsed time vary between runs.

Review focus

This PR was reviewed for merge readiness with particular attention to:

• Whether plan, query, precompute, storage, and DAG events identify the actual call or stage and include useful error detail.
• Whether error wording describes the real failure and whether normal capability misses use the right log level.
• Whether controller and backend output use a consistent layout, with the same RUST_LOG filter and info default in controller and backend.
• Whether debug events can be enabled or disabled simply, avoid credential values, and avoid duplicate completion or repeated ancestor-error messages.
• Whether compilation, formatting, focused query tests, and the required CI gate pass.
• Whether spans and events cover inner calls in the compiler, publication client, backend validation, worker, storage, and query engine, with useful identifiers and no payload dumps.

Validation

• cargo check -p control_plane -p data_plane -q
• cargo fmt --all --check
• git diff --check
• cargo clippy -p control_plane -p data_plane --all-targets -- -D warnings
• cargo test -p data_plane --lib active_metricsql_entry_reaches_the_shared_dag_executor
• cargo test -p data_plane --lib planned_range_rejects_partial_warm_coverage
• cargo test -p data_plane --lib installed_plan_rejects_unknown_queries_and_missing_samples
• cargo test -p control_plane --lib catalog_publication_posts_canonical_document_without_legacy_bytes
• cargo test -p data_plane --lib precompute_engine::subdag_scheduler::tests
• cargo test -p data_plane --test asapquery_compatibility_process_e2e shared_exact_dashboard_executes_selected_workload
• cargo clippy -p data_plane --lib -- -D warnings

Closes #755.

The restacked implementation records node start/completion/failure at the shared DAG operator boundary. It preserves runtime diagnostics without restoring the removed recursive evaluator.

Shared physical operator stack update

The shared runtime, operators and sketch codec are owned by ASAPPlanner #462, built on Planner #461. Backend #770 consumes them, #763 integrates ingestion and #765 integrates queries. The stack uses general semi-join and grouped Sort → Limit, with execution phase on the node. Independent library tests run in Planner; deployment acceptance stays in this backend stack.

Execution logs follow the composed operators and read phase from node state; removed operator variants are not retained for logging compatibility.

Dependency boundary

Based directly on #765. Diagnostic instrumentation is an independent follow-up; costing, correctness and benefit acceptance do not inherit this PR.

[milindsrivastava1997]

@zzylol

I ddded the following:

• Operator label on DAG node events (op, e.g. summary_estimate, logical/temporal): previously node events only had node_id, which meant cross-referencing the compiled plan to know which operator failed.
• Per-leaf failure logs in exact-leaf preparation and catalog validation (node_id + op): most capability misses happen here, before DAG evaluation, and were only visible as a call-level error with no node context.

[zzylol]

@milindsrivastava1997 Thanks for the logging suggestion. I made the controller and data plane consistent: both now use only RUST_LOG (default info), and the data plane --log-level flag is removed. For workflow traces, set RUST_LOG=info,asap_runtime_debug=debug on both processes.

I also expanded the installed query DAG events so every evaluated node reports its IR type (op), bounded syntax details (syntax), and input node IDs (inputs). For example, the aggregation E2E run shows logical/aggregate/sum with grouping=by(service), exact_readout/count, and logical/binary with operation=Div. The real success and failure logs are in the PR description; the focused aggregation E2E test and node-label tests pass. Full query text is omitted from the new syntax field.