Add tracing.

kani-compiler/src/kani_middle/resolve.rs

@@ -1,7 +1,7 @@
 // Copyright Kani Contributors
 // SPDX-License-Identifier: Apache-2.0 OR MIT
 //! This module contains code for resolving strings representing simple paths to
-//! `DefId`s. For the definition of a simple path, see
+//! `DefId`s for functions and methods. For the definition of a simple path, see
 //! <https://doc.rust-lang.org/reference/paths.html#simple-paths>.
 //!
 //! TODO: Extend this logic to support resolving qualified paths.
@@ -22,6 +22,9 @@ use rustc_middle::ty::TyCtxt;
 /// corresponding to trait methods.
 /// <https://github.com/model-checking/kani/issues/1997>
 pub fn resolve_path(tcx: TyCtxt, current_module: LocalDefId, path_str: &str) -> Option<DefId> {
+    let span = tracing::span!(tracing::Level::DEBUG, "path_resolution");
+    let _enter = span.enter();
+
     let path = to_path(tcx, current_module, path_str)?;
     match &path.base {
         Base::ExternPrelude => resolve_external(tcx, path.segments),
@@ -46,6 +49,12 @@ pub fn resolve_path(tcx: TyCtxt, current_module: LocalDefId, path_str: &str) ->
 /// The segments of a path.
 type Segments = VecDeque<String>;
 
+/// Generates the string representation of the path composed of these segments
+/// (it is inefficient, but we use it only in debugging output).
+fn segments_to_string(segments: &Segments) -> String {
+    segments.iter().cloned().collect::<Vec<_>>().join("::")
+}
+
 /// The "starting point" for a path.
 #[derive(Debug)]
 enum Base {
@@ -75,6 +84,8 @@ impl Path {
 /// Takes a string representation of a path and turns it into a `Path` data
 /// structure, resolving qualifiers (like `crate`, etc.) along the way.
 fn to_path(tcx: TyCtxt, current_module: LocalDefId, name: &str) -> Option<Path> {
+    tracing::debug!("Normalizing path `{name}`");
+
     const CRATE: &str = "crate";
     // rustc represents initial `::` as `{{root}}`.
     const ROOT: &str = "{{root}}";
@@ -124,22 +135,31 @@ fn to_path(tcx: TyCtxt, current_module: LocalDefId, name: &str) -> Option<Path>
     let mut base_module = current_module;
     while segments.front().map(String::as_str) == Some(SUPER) {
         segments.pop_front();
-        base_module = tcx.hir().local_def_id(parents.next()?.0);
+        let parent = parents.next().map(|p| p.0).or_else(|| {
+            tracing::debug!("Unable to normalize path `{name}`: too many `super` qualifiers");
+            None
+        })?;
+        base_module = tcx.hir().local_def_id(parent);
     }
 
     Some(Path::new(Base::LocalModule { id: base_module, may_be_external_path }, segments))
 }
 
 /// Resolves an external path.
 fn resolve_external(tcx: TyCtxt, mut segments: Segments) -> Option<DefId> {
-    let first = segments.pop_front()?;
+    tracing::debug!("Resolving `{}` in the external prelude", segments_to_string(&segments));
+    let first = segments.pop_front().or_else(|| {
+        tracing::debug!("Unable to resolve the empty path");
+        None
+    })?;
     for crate_num in tcx.crates(()) {
         let crate_name = tcx.crate_name(*crate_num);
         if crate_name.as_str() == first {
             let crate_def_id = DefId { index: CRATE_DEF_INDEX, krate: *crate_num };
             return resolve_in_foreign_module(tcx, crate_def_id, segments);
         }
     }
+    tracing::debug!("Unable to resolve `{first}` as an external crate");
     None
 }
 
@@ -149,11 +169,24 @@ fn resolve_in_foreign_module(
     foreign_mod: DefId,
     mut segments: Segments,
 ) -> Option<DefId> {
-    let first = segments.front()?;
+    tracing::debug!(
+        "Resolving `{}` in foreign module `{}`",
+        segments_to_string(&segments),
+        tcx.def_path_str(foreign_mod)
+    );
+
+    let first = segments.front().or_else(|| {
+        tracing::debug!("Unable to resolve the empty path");
+        None
+    })?;
     for child in tcx.module_children(foreign_mod) {
         match child.res {
             Res::Def(DefKind::Fn, def_id) => {
                 if first == child.ident.as_str() && segments.len() == 1 {
+                    tracing::debug!(
+                        "Resolved `{first}` as a function in foreign module `{}`",
+                        tcx.def_path_str(foreign_mod)
+                    );
                     return Some(def_id);
                 }
             }
@@ -174,6 +207,11 @@ fn resolve_in_foreign_module(
             _ => {}
         }
     }
+
+    tracing::debug!(
+        "Unable to resolve `{first}` as an item in foreign module `{}`",
+        tcx.def_path_str(foreign_mod)
+    );
     None
 }
 
@@ -183,13 +221,35 @@ fn resolve_relative(
     current_module: LocalDefId,
     mut segments: Segments,
 ) -> Option<DefId> {
-    let first = segments.front()?;
+    let current_module_string = || -> String {
+        let def_id = current_module.to_def_id();
+        if def_id.is_crate_root() {
+            "crate root".to_string()
+        } else {
+            format!("module `{}`", tcx.def_path_str(def_id))
+        }
+    };
+    tracing::debug!(
+        "Resolving `{}` in local {}",
+        segments_to_string(&segments),
+        current_module_string()
+    );
+
+    let first = segments.front().or_else(|| {
+        tracing::debug!("Unable to resolve the empty path");
+        None
+    })?;
     for item_id in tcx.hir().module_items(current_module) {
         let item = tcx.hir().item(item_id);
         let def_id = item.owner_id.def_id.to_def_id();
+        println!("ITEM {}", item.ident);
         match item.kind {
             ItemKind::Fn(..) => {
                 if first == item.ident.as_str() && segments.len() == 1 {
+                    tracing::debug!(
+                        "Resolved `{first}` as a function in local {}",
+                        current_module_string()
+                    );
                     return Some(def_id);
                 }
             }
@@ -210,30 +270,37 @@ fn resolve_relative(
             _ => (),
         }
     }
+
+    tracing::debug!("Unable to resolve `{first}` as an item in local {}", current_module_string());
     None
 }
 
 /// Resolves a name in an `impl` block.
 fn resolve_in_impl(tcx: TyCtxt, impl_id: DefId, name: &str) -> Option<DefId> {
+    tracing::debug!("Resolving `{name}` in impl block `{}`", tcx.def_path_str(impl_id));
     for assoc_item in tcx.associated_item_def_ids(impl_id) {
         let item_path = tcx.def_path_str(*assoc_item);
         let last = item_path.split("::").last().unwrap();
         if last == name {
+            tracing::debug!("Resolved `{name}` in impl block `{}`", tcx.def_path_str(impl_id));
             return Some(*assoc_item);
         }
     }
+    tracing::debug!("Unable to resolve `{name}` in impl block `{}`", tcx.def_path_str(impl_id));
     None
 }
 
 /// Resolves a name in the inherent `impl` blocks of a type (i.e., non-trait
 /// `impl`s).
 fn resolve_in_inherent_impls(tcx: TyCtxt, type_id: DefId, name: &str) -> Option<DefId> {
+    tracing::debug!("Resolving `{name}` in type `{}`", tcx.def_path_str(type_id));
     for impl_ in tcx.inherent_impls(type_id) {
         let maybe_resolved = resolve_in_impl(tcx, *impl_, name);
         if maybe_resolved.is_some() {
             return maybe_resolved;
         }
     }
+    tracing::debug!("Unable to resolve `{name}` in type `{}`", tcx.def_path_str(type_id));
     None
 }