Merge dev

.changesets/fix_geal_deduplication_processing_time.md

@@ -0,0 +1,5 @@
+### do not count the wait time in deduplication as processing time ([PR #6207](https://github.com/apollographql/router/pull/6207))
+
+waiting for a deduplicated request was incorrectly counted as time spent in the router overhead, while most of it was actually spent waiting for the subgraph response.
+
+By [@Geal](https://github.com/Geal) in https://github.com/apollographql/router/pull/6207

.changesets/fix_geal_response_validation_errors.md

@@ -0,0 +1,5 @@
+### add errors for response validation ([Issue #5372](https://github.com/apollographql/router/issues/5372))
+
+When formatting responses, the router is validating the data returned by subgraphs and replacing it with null values as appropriate. That validation phase is now adding errors when encountering the wrong type in a field requested by the client.
+
+By [@Geal](https://github.com/Geal) in https://github.com/apollographql/router/pull/5787

.changesets/fix_tninesling_remove_demand_control_warnings.md

@@ -0,0 +1,5 @@
+### Remove noisy demand control logs ([PR #6192](https://github.com/apollographql/router/pull/6192))
+
+Demand control no longer logs warnings when a subgraph response is missing a requested field.
+
+By [@tninesling](https://github.com/tninesling) in https://github.com/apollographql/router/pull/6192

.changesets/maint_bnjjj_fix_supergraph_events_span.md

@@ -0,0 +1,5 @@
+### Don't create a stub span for supergraph events if it already has a current span ([PR #6096](https://github.com/apollographql/router/pull/6096))
+
+Don't create useless span when we already have a span available to use the span's extensions.
+
+By [@bnjjj](https://github.com/bnjjj) in https://github.com/apollographql/router/pull/6096

README.md

@@ -4,11 +4,6 @@
 
 ---
 
-**Announcement:**   
-Join 1000+ engineers at GraphQL Summit for talks, workshops, and office hours, Oct 8-10 in NYC. [Get your pass here ->](https://summit.graphql.com/?utm_campaign=github_federation_readme)
-
----
-
 # Apollo Router Core
 
 The **Apollo Router Core** is a configurable, high-performance **graph router** written in Rust to run a [federated supergraph](https://www.apollographql.com/docs/federation/) that uses [Apollo Federation 2](https://www.apollographql.com/docs/federation/v2/federation-2/new-in-federation-2).

apollo-federation/src/query_graph/graph_path.rs

@@ -591,6 +591,12 @@ pub(crate) struct SimultaneousPathsWithLazyIndirectPaths {
     pub(crate) lazily_computed_indirect_paths: Vec<Option<OpIndirectPaths>>,
 }
 
+impl Display for SimultaneousPathsWithLazyIndirectPaths {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        write!(f, "{}", self.paths)
+    }
+}
+
 /// A "set" of excluded destinations (i.e. subgraph names). Note that we use a `Vec` instead of set
 /// because this is used in pretty hot paths (the whole path computation is CPU intensive) and will
 /// basically always be tiny (it's bounded by the number of distinct key on a given type, so usually

apollo-federation/src/query_plan/fetch_dependency_graph.rs

@@ -3352,11 +3352,7 @@ pub(crate) fn compute_nodes_for_tree(
     initial_defer_context: DeferContext,
     initial_conditions: &OpGraphPathContext,
 ) -> Result<IndexSet<NodeIndex>, FederationError> {
-    snapshot!(
-        "OpPathTree",
-        serde_json_bytes::json!(initial_tree.to_string()).to_string(),
-        "path_tree"
-    );
+    snapshot!("OpPathTree", initial_tree.to_string(), "path_tree");
     let mut stack = vec![ComputeNodesStackItem {
         tree: initial_tree,
         node_id: initial_node_id,
@@ -3443,7 +3439,11 @@ pub(crate) fn compute_nodes_for_tree(
             }
         }
     }
-    snapshot!(dependency_graph, "updated_dependency_graph");
+    snapshot!(
+        "FetchDependencyGraph",
+        dependency_graph.to_dot(),
+        "Fetch dependency graph updated by compute_nodes_for_tree"
+    );
     Ok(created_nodes)
 }
 

apollo-federation/src/query_plan/query_planner.rs

@@ -11,6 +11,7 @@ use apollo_compiler::ExecutableDocument;
 use apollo_compiler::Name;
 use itertools::Itertools;
 use serde::Serialize;
+use tracing::trace;
 
 use super::fetch_dependency_graph::FetchIdGenerator;
 use super::ConditionNode;
@@ -551,7 +552,15 @@ impl QueryPlanner {
             statistics,
         };
 
-        snapshot!(plan, "query plan");
+        snapshot!(
+            "QueryPlan",
+            plan.to_string(),
+            "QueryPlan from build_query_plan"
+        );
+        snapshot!(
+            plan.statistics,
+            "QueryPlanningStatistics from build_query_plan"
+        );
 
         Ok(plan)
     }
@@ -716,7 +725,11 @@ pub(crate) fn compute_root_fetch_groups(
             root_kind,
             root_type.clone(),
         )?;
-        snapshot!(dependency_graph, "tree_with_root_node");
+        snapshot!(
+            "FetchDependencyGraph",
+            dependency_graph.to_dot(),
+            "tree_with_root_node"
+        );
         compute_nodes_for_tree(
             dependency_graph,
             &child.tree,
@@ -737,16 +750,13 @@ fn compute_root_parallel_dependency_graph(
     parameters: &QueryPlanningParameters,
     has_defers: bool,
 ) -> Result<FetchDependencyGraph, FederationError> {
-    snapshot!(
-        "FetchDependencyGraph",
-        "Empty",
-        "Starting process to construct a parallel fetch dependency graph"
-    );
+    trace!("Starting process to construct a parallel fetch dependency graph");
     let selection_set = parameters.operation.selection_set.clone();
     let best_plan = compute_root_parallel_best_plan(parameters, selection_set, has_defers)?;
     snapshot!(
-        best_plan.fetch_dependency_graph,
-        "Plan returned from compute_root_parallel_best_plan"
+        "FetchDependencyGraph",
+        best_plan.fetch_dependency_graph.to_dot(),
+        "Fetch dependency graph returned from compute_root_parallel_best_plan"
     );
     Ok(best_plan.fetch_dependency_graph)
 }
@@ -807,7 +817,8 @@ fn compute_plan_internal(
 
         let (main, deferred) = dependency_graph.process(&mut *processor, root_kind)?;
         snapshot!(
-            dependency_graph,
+            "FetchDependencyGraph",
+            dependency_graph.to_dot(),
             "Plan after calling FetchDependencyGraph::process"
         );
         // XXX(@goto-bus-stop) Maybe `.defer_tracking` should be on the return value of `process()`..?

apollo-federation/src/query_plan/query_planning_traversal.rs

@@ -46,8 +46,17 @@ use crate::schema::position::CompositeTypeDefinitionPosition;
 use crate::schema::position::ObjectTypeDefinitionPosition;
 use crate::schema::position::SchemaRootDefinitionKind;
 use crate::schema::ValidFederationSchema;
+use crate::utils::logging::format_open_branch;
 use crate::utils::logging::snapshot;
 
+#[cfg(feature = "snapshot_tracing")]
+mod snapshot_helper {
+    // A module to import functions only used within `snapshot!(...)` macros.
+    pub(crate) use crate::utils::logging::closed_branches_to_string;
+    pub(crate) use crate::utils::logging::open_branch_to_string;
+    pub(crate) use crate::utils::logging::open_branches_to_string;
+}
+
 // PORT_NOTE: Named `PlanningParameters` in the JS codebase, but there was no particular reason to
 // leave out to the `Query` prefix, so it's been added for consistency. Similar to `GraphPath`, we
 // don't have a distinguished type for when the head is a root vertex, so we instead check this at
@@ -113,13 +122,33 @@ pub(crate) struct QueryPlanningTraversal<'a, 'b> {
 }
 
 #[derive(Debug, Serialize)]
-struct OpenBranchAndSelections {
+pub(crate) struct OpenBranchAndSelections {
     /// The options for this open branch.
     open_branch: OpenBranch,
     /// A stack of the remaining selections to plan from the node this open branch ends on.
     selections: Vec<Selection>,
 }
 
+impl std::fmt::Display for OpenBranchAndSelections {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        let Some((current_selection, remaining_selections)) = self.selections.split_last() else {
+            return Ok(());
+        };
+        format_open_branch(f, &(current_selection, &self.open_branch.0))?;
+        write!(f, " * Remaining selections:")?;
+        if remaining_selections.is_empty() {
+            writeln!(f, " (none)")?;
+        } else {
+            // Print in reverse order since remaining selections are processed in that order.
+            writeln!(f)?; // newline
+            for selection in remaining_selections.iter().rev() {
+                writeln!(f, "   - {selection}")?;
+            }
+        }
+        Ok(())
+    }
+}
+
 struct PlanInfo {
     fetch_dependency_graph: FetchDependencyGraph,
     path_tree: Arc<OpPathTree>,
@@ -284,7 +313,17 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
         )
     )]
     fn find_best_plan_inner(&mut self) -> Result<Option<&BestQueryPlanInfo>, FederationError> {
-        while let Some(mut current_branch) = self.open_branches.pop() {
+        while !self.open_branches.is_empty() {
+            snapshot!(
+                "OpenBranches",
+                snapshot_helper::open_branches_to_string(&self.open_branches),
+                "Query planning open branches"
+            );
+            let Some(mut current_branch) = self.open_branches.pop() else {
+                return Err(FederationError::internal(
+                    "Branch stack unexpectedly empty during query plan traversal",
+                ));
+            };
             let Some(current_selection) = current_branch.selections.pop() else {
                 return Err(FederationError::internal(
                     "Sub-stack unexpectedly empty during query plan traversal",
@@ -293,7 +332,7 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
             let (terminate_planning, new_branch) =
                 self.handle_open_branch(&current_selection, &mut current_branch.open_branch.0)?;
             if terminate_planning {
-                trace!("Planning termianted!");
+                trace!("Planning terminated!");
                 // We clear both open branches and closed ones as a means to terminate the plan
                 // computation with no plan.
                 self.open_branches = vec![];
@@ -330,12 +369,10 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
         let mut new_options = vec![];
         let mut no_followups: bool = false;
 
-        snapshot!(name = "Options", options, "options");
-
         snapshot!(
-            "OperationElement",
-            operation_element.to_string(),
-            "operation_element"
+            "OpenBranch",
+            snapshot_helper::open_branch_to_string(selection, options),
+            "open branch"
         );
 
         for option in options.iter_mut() {
@@ -368,7 +405,11 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
             }
         }
 
-        snapshot!(new_options, "new_options");
+        snapshot!(
+            "OpenBranch",
+            snapshot_helper::open_branch_to_string(selection, &new_options),
+            "new_options"
+        );
 
         if no_followups {
             // This operation element is valid from this option, but is guarantee to yield no result
@@ -610,8 +651,8 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
     )]
     fn compute_best_plan_from_closed_branches(&mut self) -> Result<(), FederationError> {
         snapshot!(
-            name = "ClosedBranches",
-            self.closed_branches,
+            "ClosedBranches",
+            snapshot_helper::closed_branches_to_string(&self.closed_branches),
             "closed_branches"
         );
 
@@ -622,8 +663,8 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
         self.reduce_options_if_needed();
 
         snapshot!(
-            name = "ClosedBranches",
-            self.closed_branches,
+            "ClosedBranches",
+            snapshot_helper::closed_branches_to_string(&self.closed_branches),
             "closed_branches_after_reduce"
         );
 
@@ -653,7 +694,7 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
         let (first_group, second_group) = self.closed_branches.split_at(sole_path_branch_index);
 
         let initial_tree;
-        snapshot!("FetchDependencyGraph", "", "Generating initial dep graph");
+        trace!("Generating initial fetch dependency graph");
         let mut initial_dependency_graph = self.new_dependency_graph();
         let federated_query_graph = &self.parameters.federated_query_graph;
         let root = &self.parameters.head;
@@ -678,21 +719,32 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
                 self.parameters.config.type_conditioned_fetching,
             )?;
             snapshot!(
-                initial_dependency_graph,
+                "FetchDependencyGraph",
+                initial_dependency_graph.to_dot(),
                 "Updated dep graph with initial tree"
             );
             if first_group.is_empty() {
                 // Well, we have the only possible plan; it's also the best.
                 let cost = self.cost(&mut initial_dependency_graph)?;
-                self.best_plan = BestQueryPlanInfo {
+                let best_plan = BestQueryPlanInfo {
                     fetch_dependency_graph: initial_dependency_graph,
                     path_tree: initial_tree.into(),
                     cost,
-                }
-                .into();
+                };
 
-                snapshot!(self.best_plan, "best_plan");
+                snapshot!(
+                    "FetchDependencyGraph",
+                    best_plan.fetch_dependency_graph.to_dot(),
+                    "best_plan.fetch_dependency_graph"
+                );
+                snapshot!(
+                    "OpPathTree",
+                    best_plan.path_tree.to_string(),
+                    "best_plan.path_tree"
+                );
+                snapshot!(best_plan.cost, "best_plan.cost");
 
+                self.best_plan = best_plan.into();
                 return Ok(());
             }
         }
@@ -723,14 +775,25 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
             other_trees,
             /*plan_builder*/ self,
         )?;
-        self.best_plan = BestQueryPlanInfo {
+        let best_plan = BestQueryPlanInfo {
             fetch_dependency_graph: best.fetch_dependency_graph,
             path_tree: best.path_tree,
             cost,
-        }
-        .into();
+        };
+
+        snapshot!(
+            "FetchDependencyGraph",
+            best_plan.fetch_dependency_graph.to_dot(),
+            "best_plan.fetch_dependency_graph"
+        );
+        snapshot!(
+            "OpPathTree",
+            best_plan.path_tree.to_string(),
+            "best_plan.path_tree"
+        );
+        snapshot!(best_plan.cost, "best_plan.cost");
 
-        snapshot!(self.best_plan, "best_plan");
+        self.best_plan = best_plan.into();
         Ok(())
     }
 
@@ -975,7 +1038,11 @@ impl<'a: 'b, 'b> QueryPlanningTraversal<'a, 'b> {
             )?;
         }
 
-        snapshot!(dependency_graph, "updated_dependency_graph");
+        snapshot!(
+            "FetchDependencyGraph",
+            dependency_graph.to_dot(),
+            "updated_dependency_graph"
+        );
         Ok(())
     }